Waiting for completion of URL

I just installed mod_pagespeed on my centos 7 and got tons of httpd errors log
in 1 minute. An example line of error:
<code>
[Tue Feb 10 11:05:14.311755 2015] [pagespeed:warn] [pid 21132:tid
139634310850304] [mod_pagespeed <IP_ADDRESS>-4448 @21132] Waiting for completion of
URL http://exampledomain.com/example-slug/ for 45.001 sec
</code>

ALL requests got error, include image requests too.

My server hardware specs:
* Intel(R) Xeon(R) CPU E3-1246 v3 @ 3.50GHz, 8 cores
* 32 GB DDR3 RAM
* 2 x 2 TB SATA 6 Gb/s 7200 rpm HDD (Software-RAID 1) Class Enterprise

Software specs:
Operating system: CentOS Linux 7.0.1406
Kernel:	Linux 3.10.0-123.20.1.el7.x86_64 on x86_64

Server Version: Apache/2.4.6 (CentOS) OpenSSL/1.0.1e-fips mod_fcgid/2.3.9
PHP/5.6.5 mod_perl/2.0.9dev Perl/v5.16.3
Server MPM: event

What version of the product are you using (please check X-Mod-Pagespeed
header)?
mod-pagespeed-stable-<IP_ADDRESS>-4448.x86_64

URL of broken page:
I removed module after 1 minute of terror. If a google developer want to learn
more of server information, mail me an ip address that i can give permission to
look mod_info print.

Original issue reported on code.google.com by<EMAIL_ADDRESS>on 10 Feb 2015 at 9:35

Hi,
same issue with Debian 7.8 64bits / Apache 2.2.22.
I had to disable the module to prevent crash (got 2 in less than a month)

@Cyriltra did you have IPRO enabled? it is enabled by default on 1.9.32.x

@crowell yes i left it enable (by default). I didn't try to disable it as another user said before it still not fix the issue for him. So I didn't dare to take that risk as I was in rush to fix the issue.
I'll give a try this weekend

This looks very suspicious:
void ApacheFetch::Wait() {
  ScopedMutex lock(mutex_.get());
  while (!done_) { ... }
}
...
void ApacheFetch::HandleDone(bool success) {
  ScopedMutex lock(mutex_.get());
  done_ = true;
}

@jeffkaufman fwiw, looks like something that could very well explain the behaviour described here to me indeed.

Looking more and talking to @jmarantz that's suspicious but actually things working properly.  In the snipped code theres a Condvar:
mutex_(server_context->thread_system()->NewMutex()),
condvar_(mutex_->NewCondvar()),
...
void ApacheFetch::Wait() {
  ScopedMutex lock(mutex_.get());
  while (!done_) {
    condvar_->TimedWait(blocking_fetch_timeout_ms_);
  }
}
...
void ApacheFetch::HandleDone(bool success) {
  ScopedMutex lock(mutex_.get());
  done_ = true;
  condvar_->Signal();
}

I believe, but I haven't verified, that the lock is released while in a timed wait on the condvar, and then when you signal the condvar it wakes up and grabs the lock again.

Verfied about the condvar.  TimedWait() delegates to pthread_cond_timedwait.

InstawebHandler::~InstawebHandler() {
  WaitForFetch();
}

I might have an unnatural focus on shutting down :-)
But what happens during when Apache recycles worker processes (assuming it does that)? Will ApacheFetch::Done be called somehow? If not, these wait calls might not ever stop waiting.

@oschaaf All our uses of ApacheFetch should look like:

MakeFetch()
SomeFetcher->Fetch(fetch)
WaitForFetch()

Which I think means WaitForFetch() in the destructor should never be called.

It should also quick-exit because done is already true.
On Fri, Apr 10, 2015 at 9:12 AM, Jeff Kaufman<EMAIL_ADDRESS>wrote:

@oschaaf https://github.com/oschaaf All our uses of ApacheFetch should
look like:

MakeFetch()
SomeFetcher->Fetch(fetch)
WaitForFetch()

Which I think means WaitForFetch() in the destructor should never be
called.
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-91552185
.

@morlovich What would happen when a BoundedWait() call for a driver times out during ServerContext::ShutDown()?

For debugging this, it would be useful to look at the pagespeed configuration files for the different sites that are having this problem.  If this problem has happened to you, could you send your server configuration file to<EMAIL_ADDRESS>

Hello,
Have the same problem :  Waiting for completion of URL
On some pictures, seems to be direct access to page with no html, or script (jpg ... shown in browser).
http://domain.tld/picture.jpg
I have send logs and server configuration file to jeffkaufman.
Greatings,
Eric

Follow-up from a recent message on the same symptom to mod-pagespeed-discuss revealed that this can be repro'd without memcached.  In this particular case the file-cache was a on a path that looked suspiciously like it might be a network file system.  Slow response from any file-system could cause this message to come out, but I'd be particularly suspicious of a network file system.

Also, re: memcached --- the report that had logs with broken pipe errors
with AprMemCached, those seem to be associated with use of haproxy with
memcached, but also seem
to be a false lead --- we appear to recover from them, at least per my
loadtests.
On Fri, May 1, 2015 at 9:50 AM, jmarantz<EMAIL_ADDRESS>wrote:

Follow-up from a recent message on the same symptom to
mod-pagespeed-discuss revealed that this can be repro'd without memcached.
In this particular case the file-cache was a on a path that looked
suspiciously like it might be a network file system. Slow response from any
file-system could cause this message to come out, but I'd be particularly
suspicious of a network file system.
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-98138804
.

Hello,
Here : https://github.com/pagespeed/mod_pagespeed/issues/1072
It's said that disabled IPRO should be used as workaround.
So, as said here : https://developers.google.com/speed/pagespeed/module/system in In-Place Resource Optimization what url will be used for example in Google Image : original one ?
I'm new to mod_pagespeed, and doesn't want to loose some refered position in Google Image by changing urls for direct access to images.
What will happened to those urls if IPRO is not used.
Thanks,
Eric

To clarify, in-place resource optimization allows images to be modified,
but does not prevent them from being renamed, which is what mod_pagespeed
normally does. This was originally created to address the situation where
images were loaded from JavaScript, and thus PageSpeed had no opportunity
to rename them.
To prevent images from being renamed you need to use ImagePreserveUrls
https://developers.google.com/speed/pagespeed/module/config_filters#preserveurls.
And if you do that with IPRO off then PageSpeed will not be able to
optimize your images.
RE image-search rank: what makes you think you are going to lose image rank
if their URLs are changed?
-Josh
On Mon, May 4, 2015 at 7:09 PM, eldk<EMAIL_ADDRESS>wrote:

Hello,
Here : #1072 https://github.com/pagespeed/mod_pagespeed/issues/1072
It's said that disabled IPRO should be used as workaround.
So, as said here :
https://developers.google.com/speed/pagespeed/module/system in In-Place
Resource Optimization what url will be used for example in Google Image :
original one ?
I'm new to mod_pagespeed, and doesn't want to loose some refered position
in Google Image by changing urls for direct access to images.
What will happened to those urls if IPRO is not used.
Thanks,
Eric
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-98881384
.

Hello,
I have just disabled IPRO for 24h00 now with "ModPagespeedInPlaceResourceOptimization off" in pagespeed.conf,
All the "waiting for completion of URL" messages have disappeared.
Due to bandwith usage change beetwen IPRO OFF and IPRO ON, I think the error happened only for some ressources.
One off the URL which was the most seen in mod_pagespeed log when "waiting for completion of URL" happened was a direct access (without html - Content-Type: image/jpeg) to http://www.opalesurfcasting.net/IMG/truite_et_saumon_atlantique.jpg .
Checking the cache for this image in "/pagespeed_admin/cache#show_metadata" gives :`
Metadata cache key:rname/aj_pBqmmsYhv0uO-3TvxlU9/http://www.opalesurfcasting.net/IMG/truite_et_saumon_atlantique.jpg@@_
cache_ok:false
can_revalidate:false
partitions:
When IPRO is ON, refresh the page in FIREFOX with cache disabled rewrite the image and "/pagespeed_admin/cache#show_metadata" gives cache_ok:true, but "waiting for completion in url" still occurs.
Sometimes "waiting for completion of URL" happened too with a javascript (SIG Layer, openlayers/geoportail API).
image-search rank : I'm not sure. But maybe duplicate content for images or ... ?
Greatings,
Eric

We had a meeting offline to work on this bug.  Some things that came out of that:

We're not stuck on a slow blocking call because that would have shown up in the backtraces we got from gdb.
It's probably some rare situation in which a callback is being missed, most likely because of a race.
What that same situation happens in Nginx the equivalent of ApacheFetch doesn't exist and so Nginx times out the request instead of tying up an Apache process indefinitely.
One fix would be to make ApacheFetch::Wait() time out and log an error after a long enough wait.
This would not fix the underlying bug, but would put Apache into the same situation as Nginx, where the bug is rare and affects only that one request.

Ideas for more places to look for the underlying bug:

IPRO has a CacheUrlAsyncFetcher, which might be using vestigial fetch locks; what happens if we fail to get the lock because two requests come in right together?
We have locking to avoid optimizing a resource multiple times at once.  What happens if we fail to get that lock in the ipro flow?
AsyncFetchWithLock::Start is suspicious, but I don't remember seeing "is already being fetched" in people's logs

Hello,
I have made some tests this night with IPRO ON.
As I "understand", IPRO may rewrite images when direct access it/not asked in HTML.
For the first call, if image is not in the client browser cache, a copy of original image is done in the folder /var/cache/mod_pagespeed/domain/imagefolder/.
After n next calls with 200 apache answer, a rewrited minimized ... image is created and then served to the client,
So I still have the "waiting for completion of URL" warning. But rewrited images are created in cache, served to the client with good type, webp (Chrome) or jpg (Firefox).  There is a warning, but rewriting have been well done.
For those test, I have stopped apache, renamed /var/cache/mod_pagespeed/ folder, then created a new one which is readable and writable by apache user and group. At restart, apache recreated
the domain subfolder, may read and write to it. But I can't find any rname folder. Is this folder absolutely needed and what is creating it ? Where should I find a doc on what is rname folder ?
Greatings,
Eric
Version: 13: on
Filters
cw	Collapse Whitespace
gp	Convert Gif to Png
jp	Convert Jpeg to Progressive
jw	Convert Jpeg To Webp
pj	Convert Png to Jpeg
hw	Flushes html
ci	Inline Css
io	In-place optimize for browser
js	Jpeg Subsampling
rj	Recompress Jpeg
rp	Recompress Png
rw	Recompress Webp
rc	Remove Comments
cf	Rewrite Css
jm	Rewrite External Javascript
jj	Rewrite Inline Javascript
cp	Strip Image Color Profiles
md	Strip Image Meta Data
Options
EnableCachePurge (euci)             False
EnableRewriting (e)                 1
FileCacheCleanIntervalMs (afcci)    3600000
FileCacheInodeLimit (afcl)          500000
FileCachePath (afcp)                /var/cache/mod_pagespeed/
FileCacheSizeKb (afc)               2048000
InPlaceResourceOptimization (ipro)  True
LogDir (ald)                        /var/log/pagespeed
RewriteLevel (l)                    Optimize For Bandwidth
SslCertDirectory (assld)            /etc/ssl/certs
StatisticsLogging (asle)            True
Domain Lawyer
Invalidation Timestamp: (none)

So I still have the "waiting for completion of URL" warning. But rewrited images are created in cache,
served to the client with good type, webp (Chrome) or jpg (Firefox). There is a warning, but rewriting
have been well done.

When you were testing this were there any responses that hung or otherwise didn't return a valid image?
When you got the "waiting for completion of URL" message, how many times did it show up?  Just a few or was it printing every 5s until you shut down the server?

For those test, I have stopped apache, renamed /var/cache/mod_pagespeed/ folder, then created a new one which is readable and writable by apache user and group. At restart, apache recreated
the domain subfolder, may read and write to it. But I can't find any rname folder. Is this folder absolutely needed and what is creating it ? Where should I find a doc on what is rname folder ?

Apache will recreate the rname folder when it's needed.  That's the metadata cache, storing information about things like "when you optimize the image with url X you get the image we've stored at url Y in the http cache".
In general, the best way to flush the pagespeed cache is to tell pagespeed to do the flushing: https://developers.google.com/speed/pagespeed/module/system#flush_cache

Hello,

When you were testing this were there any responses that hung or otherwise didn't return a valid image?
No, no hung, always valid images.
When you got the "waiting for completion of URL" message, how many times did it show up? Just a >few or was it printing every 5s until you shut down the server?
I'm using FCGID so I think no task from apache could hang indefinitely without been forced to close.
The "waiting for completion " could occure the first time the image is called, and for what I have seen being repeted a few times until 450 secondes max.

When an image is in cache, the message should come back later thus the cached image is served.
One response header for that case in Firefox:`
...
Date: Thu, 07 May 2015 16:34:36 GMT
Content-Length: 1256601
Accept-Ranges: bytes
Etag: W/"PSA-aj-oe4DUPjTLN"
Expires: Tue, 03 Nov 2015 03:54:37 GMT
Cache-Control: max-age=15506400
Vary: Accept
Last-Modified: Thu, 07 May 2015 16:34:36 GMT
X-Content-Type-Options: nosniff
Keep-Alive: timeout=5, max=100
Connection: Keep-Alive
Content-Type: image/jpeg
200 OK
...
Content- lenght is the same as rewrited image and the etag is the one stored in the rewrite image file name : 11256876 mai    7 05:55 xyeux-anguille-anguilla-anguilla.jpg.pagespeed.ic.oe4DUPjTLN.jpg,
[Thu May 07 18:35:55 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @13509] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/jpg/yeux-anguille-anguilla-anguilla.jpg for 10.025 sec
at 18h41 GMT+2 no file has been recreated or modified.
Greatings,
Eric

Hello again,
I found now some message "waiting ..." for some images still embedded in HTML.(Serf)
Here it's the same, good resized image (Etag) served but warning message.
grep in access log :`
[07/May/2015:18:18:56 +0200] "GET /IMG/cache-300x200/IMG_3711_v1-300x200.jpg HTTP/1.1" 200 18060 "http://www.google.fr/" "Mozilla/5.0 (Linux; Android 4.4.2; SM-G800F Build/KOT49H) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.109 Mobile Safari/537.36"
It's a direct access to image, from a google images search request :
[07/May/2015:18:18:56 +0200] "GET /IMG/cache-300x200/IMG_3711_v1-300x200.jpg HTTP/1.1" 200 18060 "http://www.google.fr/" "Mozilla/5.0 (Linux; Android 4.4.2; SM-G800F Build/KOT49H) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.109 Mobile Safari/537.36"
Greatings,
Eric

Since this is probably caused by the IPRO flow in PSOL not calling a callback under unusual circumstances, I went through and traced the callbacks in this flow:

All IPRO requests:

RewriteContext::Fetch calls RewriteDriver::AddRewriteTask to get RewriteContext::StartFetch called on the rewrite thread (or RewriteContext::CancelFetch if cancelled).
RewriteContext::StartFetchImpl calls Get() on the metadata cache, to get RewriteContext::FetchCacheDone called with the results of the metadata cache lookup.
First (nothing in cache) or second request (recorded resource in cache)

CacheUrlAsyncFetcher::Fetch calls Find() on the http cache to get CacheFindCallback::Done called with the results of the http cache lookup.

Third (optimized resource in cache):

RewriteContext::FetchTryFallback calls Find() on the http cache to get RewriteContext::FetchFallbackCacheDone called with the results of the http cache lookup

Hello,
Thus images are all rewrited (jpg and webp).
There are still "waiting for completion .." messages.
For example :
Call to this image :
Apache access log :
[08/May/2015:11:03:19 +0200] "GET /IMG/montage_1_clipot_creux.jpg HTTP/1.1" 200 683251 "-" "Mozilla/5.0 (Linux; Android 4.4.2; K00Z Build/KVT49L) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/<IP_ADDRESS> Safari/537.36 GSA/<IP_ADDRESS>.x86"
For which all have been rewrited :
1529415 mai    7 08:54 montage_1_clipot_creux.jpg,
476402 mai    7 09:20 xmontage_1_clipot_creux.jpg.pagespeed.ic.57rrAy504D.jpg,
481435 mai    7 18:18 xmontage_1_clipot_creux.jpg.pagespeed.ic.bljlr_GZ6w.webp,
683124 mai    7 09:35 xmontage_1_clipot_creux.jpg.pagespeed.ic.jAD6QblrdB.jpg,
350413 mai    7 12:30 xmontage_1_clipot_creux.jpg.pagespeed.ic.XsQS4awGxO.webp,
Still spawn warnings :
[Fri May 08 11:03:24 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 5 sec
[Fri May 08 11:03:29 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 10.005 sec
[Fri May 08 11:03:34 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 15.015 sec
[Fri May 08 11:03:39 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 20.015 sec
[Fri May 08 11:03:44 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 25.063 sec
[Fri May 08 11:03:49 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 30.16 sec
[Fri May 08 11:03:54 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 35.16 sec
[Fri May 08 11:04:00 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 40.28 sec
[Fri May 08 11:04:05 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 45.281 sec
[Fri May 08 11:04:10 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 50.281 sec
[Fri May 08 11:04:15 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @32387] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/montage_1_clipot_creux.jpg for 55.297 sec
I will follow the logs for that image to see if it's happened for every call.
Greatings,
Eric

I hit this one on a busy server tonight.
We do not use memcached or InPlaceResourceOptimization.
We do use LoadFromFileMatch and ModPagespeedMapOriginDomain.
One of the vhosts that experienced this problem tonight has the following config
Inherited:
ModPagespeed on
ModPagespeedRespectXForwardedProto on
ModPagespeedRewriteLevel PassThrough
ModPagespeedForbidAllDisabledFilters false
ModPagespeedDefaultSharedMemoryCacheKB 100000
ModPagespeedLoadFromFileRuleMatch disallow .*
ModPagespeedLoadFromFileRuleMatch allow \.(css|js|png|jpg|webp|gif|ico|ttf|woff)$

ModPagespeedNumRewriteThreads 3
ModPagespeedNumExpensiveRewriteThreads 1
ModPagespeedRewriteRandomDropPercentage 10
ModPagespeedRewriteDeadlinePerFlushMs 15

vhost-spesific:
ModPagespeed on
ModPagespeedFileCachePath '/kunder/xx/zz/pagespeed-cache'
ModPagespeedMapOriginDomain 'http://domain.com:8000' 'http://domain.com'
ModPagespeedMapOriginDomain 'http://domain.com:8000' 'https://domain.com'
ModPagespeedLoadFromFile 'http://domain.com/' '/kunder/xx/yy/public'
ModPagespeedCombineAcrossPaths on
ModPagespeedEnableFilters recompress_jpeg,recompress_png,convert_to_webp_lossless,collapse_whitespace,elide_attributes,trim_urls,prioritize_critical_css,remove_quotes,remove_comments,rewrite_javascript,inline_javascript,combine_javascript,combine_css,rewrite_style_attributes,move_css_to_head,move_css_above_scripts,fallback_rewrite_css_urls,rewrite_css,inline_import_to_link,inline_css,flatten_css_imports,sprite_images,insert_image_dimensions,resize_images,recompress_webp,convert_jpeg_to_webp,convert_jpeg_to_progressive,inline_preview_images,resize_mobile_images,dedup_inlined_images,insert_dns_prefetch
The above config lines have been modified obviously. There are several more MapOriginDomain and LoadFromFile (all pointing to same folder and to the same source url).
I might be able to email the configfiles and logfiles on request, it has a loglevel of 'notify' so it is quite verbose (although nothing really seems to stand out that I could see).

Hans -- you mean you saw the "Waiting for Completion" spinning message in
your log file?  And you don't have ipro on, and you don't have
MapProxyDomain either?
Can you paste the exact message you saw?
-Josh
On Fri, May 8, 2015 at 7:16 AM, Hans Kristian Rosbach <
<EMAIL_ADDRESS>wrote:

I hit this one on a busy server tonight.
We do not use memcached or InPlaceResourceOptimization.
We do use LoadFromFileMatch and ModPagespeedMapOriginDomain.
One of the vhosts that experienced this problem tonight has the following
config
Inherited:
ModPagespeed on
ModPagespeedRespectXForwardedProto on
ModPagespeedRewriteLevel PassThrough
ModPagespeedForbidAllDisabledFilters false
ModPagespeedDefaultSharedMemoryCacheKB 100000
ModPagespeedLoadFromFileRuleMatch disallow .*
ModPagespeedLoadFromFileRuleMatch allow .(css|js|png|jpg|webp|gif|ico|ttf|woff)$
ModPagespeedNumRewriteThreads 3
ModPagespeedNumExpensiveRewriteThreads 1
ModPagespeedRewriteRandomDropPercentage 10
ModPagespeedRewriteDeadlinePerFlushMs 15
vhost-spesific:
ModPagespeed on
ModPagespeedFileCachePath '/kunder/xx/zz/pagespeed-cache'
ModPagespeedMapOriginDomain 'http://domain.com:8000' 'http://domain.com'
ModPagespeedMapOriginDomain 'http://domain.com:8000' 'https://domain.com'
ModPagespeedLoadFromFile 'http://domain.com/' '/kunder/xx/yy/public'
ModPagespeedCombineAcrossPaths on
ModPagespeedEnableFilters
recompress_jpeg,recompress_png,convert_to_webp_lossless,collapse_whitespace,elide_attributes,trim_urls,prioritize_critical_css,remove_quotes,remove_comments,rewrite_javascript,inline_javascript,combine_javascript,combine_css,rewrite_style_attributes,move_css_to_head,move_css_above_scripts,fallback_rewrite_css_urls,rewrite_css,inline_import_to_link,inline_css,flatten_css_imports,sprite_images,insert_image_dimensions,resize_images,recompress_webp,convert_jpeg_to_webp,convert_jpeg_to_progressive,inline_preview_images,resize_mobile_images,dedup_inlined_images,insert_dns_prefetch
The above config lines have been modified obviously. There are several
more MapOriginDomain and LoadFromFile (all pointing to same folder and to
the same source url).
I might be able to email the configfiles and logfiles on request, it has a
loglevel of 'notify' so it is quite verbose (although nothing really seems
to stand out that I could see).
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-100197419
.

That is right, no MapProxyDomain and no ipro.
I even did a grep on all config files now just in case, they are not and cannot (by a non-root user) be enabled on this server.
The initial four warnings:
[Fri May 08 05:11:09.940940 2015] [pagespeed:warn] [pid 92559] [mod_pagespeed <IP_ADDRESS>-4448 @92559] Waiting for completion of URL http://domain.com/wp-content/uploads/2014/06/11.jpg for 5 sec
[Fri May 08 05:11:14.941139 2015] [pagespeed:warn] [pid 92559] [mod_pagespeed <IP_ADDRESS>-4448 @92559] Waiting for completion of URL http://domain.com/wp-content/uploads/2014/06/11.jpg for 10.001 sec
[Fri May 08 05:11:19.941315 2015] [pagespeed:warn] [pid 92559] [mod_pagespeed <IP_ADDRESS>-4448 @92559] Waiting for completion of URL http://domain.com/wp-content/uploads/2014/06/11.jpg for 15.001 sec
[Fri May 08 05:11:24.941497 2015] [pagespeed:warn] [pid 92559] [mod_pagespeed <IP_ADDRESS>-4448 @92559] Waiting for completion of URL http://domain.com/wp-content/uploads/2014/06/11.jpg for 20.001 sec

Oh, sorry for the confusion.  You are using 1.9, so unless you turn it off
specifically, you have ipro.  TO turn it off, use
ModPagespeedInPlaceResourceOptimization off
On Fri, May 8, 2015 at 8:33 AM, Hans Kristian Rosbach <
<EMAIL_ADDRESS>wrote:

That is right, no MapProxyDomain and no ipro.
I even did a grep on all config files now just in case, they are not and
cannot (by a non-root user) be enabled on this server.
The initial four warnings:
[Fri May 08 05:11:09.940940 2015] [pagespeed:warn] [pid 92559] [mod_pagespeed <IP_ADDRESS>-4448 @92559] Waiting for completion of URL http://domain.com/wp-content/uploads/2014/06/11.jpg for 5 sec
[Fri May 08 05:11:14.941139 2015] [pagespeed:warn] [pid 92559] [mod_pagespeed <IP_ADDRESS>-4448 @92559] Waiting for completion of URL http://domain.com/wp-content/uploads/2014/06/11.jpg for 10.001 sec
[Fri May 08 05:11:19.941315 2015] [pagespeed:warn] [pid 92559] [mod_pagespeed <IP_ADDRESS>-4448 @92559] Waiting for completion of URL http://domain.com/wp-content/uploads/2014/06/11.jpg for 15.001 sec
[Fri May 08 05:11:24.941497 2015] [pagespeed:warn] [pid 92559] [mod_pagespeed <IP_ADDRESS>-4448 @92559] Waiting for completion of URL http://domain.com/wp-content/uploads/2014/06/11.jpg for 20.001 sec
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-100218658
.

I have seen .jpg, .cs and .js files in waiting.
One strange thing though is that the url it is waiting to download from is not the one specified in the config files using ModPagespeedMapOriginDomain.
So at least according to the message, it is attempting to download the file from the frontend nginx instead of the backend apache at port 8000. This would then loop since nginx asks apache, and possibly nginx is waiting for the previous (the initial) request for that file to complete so it can deliver a cached version..?
Or is it just a wrong error message, just displaying the wrong url?

@jmarantz Ah, now that you mention it, I remember seeing that in the changelog. So yes, then ipro is probably enabled.

The URL is printed in the error message prior to mapping it with
MapOriginDomain, so I'm not worried about that.
It looks like based on your directives,
http://domain.com/wp-content/uploads/2014/06/11.jpg should be stored in
'/kunder/xx/yy/public/wp-content/uploads/2014/06/11.jpg'.  Is it there?
I wonder if this is an interaction between ipro and URLs which match our
LoadFromFile path, but are missing.
In the non-ipro case, we would simply not optimize such resources.
Note that we do not fallback to http fetches when a URL in the
load-from-file path is missing; we just fail to do the fetch.
-Josh
On Fri, May 8, 2015 at 8:40 AM, Hans Kristian Rosbach <
<EMAIL_ADDRESS>wrote:

I have seen .jpg, .cs and .js files in waiting.
One strange thing though is that the url it is waiting to download from is
not the one specified in the config files using ModPagespeedMapOriginDomain.
So at least according to the message, it is attempting to download the
file from the frontend nginx instead of the backend apache at port 8000.
This would then loop since nginx asks apache, and possibly nginx is waiting
for the previous (the initial) request for that file to complete so it can
deliver a cached version..?
Or is it just a wrong error message, just displaying the wrong url?
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-100221403
.

The file exists and has been there for 7 months.

It appears that not only static files are affected.
These are the variations that failed, including 3 php scripts and those dont match the LoadFromFileRuleMatch.
http://domain1.com/wp-content/uploads/2014/06/11.jpg
http://domain2.com/?page=30
http://domain3.com/wp-content/plugins/gravityforms/js/jquery.maskedinput-1.3.1.min.js?ver=1.8.17
http://domain3.com/wp-includes/css/admin-bar.min.css?ver=4.1.2
http://domain5.com/wp-content/themes/feast/images/miljofyrtaarn.png
http://domain5.com/wp-content/themes/feast/images/prevver.png
http://domain6.com/nettbutikk-2/?filter_typekaffe=82&filter_land=104&filter_storrelse=84,85,86
http://domain7.com/

Hello,
I'm going on the tests.
Should a restart of apache make the cache rewriting  images again, thus the rewrited images were in the cache  ?
Greatings.
Eric

@eldk I'm not sure if this is what you're asking, but no, restarting Apache won't clear the cache.  To do that you need https://developers.google.com/speed/pagespeed/module/system#flush_cache

Hello,
@jeffkaufman
I try to be more understandable.
I want to know, if when apache is restarted, the images in the cache, the original one, and the rewrited images (2 jpg + 2 webp) are rewrited again (not flush but rewrited).
a  ls -al nameofimage give the time of modification of the image file.
When I restart apache (sudo service apache2 restart), the time of modification is update as if the images were rewrited again and I think they are.
Is it the expected behaviour ?
Greatings,
Eric

Hello,
I have change some parameters in my mod_pagespeed.conf, use of ModPagespeedLoadFromFile for my image directory.
I have less "waiting from completion ..." messages.
The message  that give more than 5 seconds waiting time are less than 90%.
Those messages which give longer waiting times seem to have common things :

thus the apache log give a 200 answer for the request, the size of the file is not good : less than the size of original and rewrited images.
when the user, push a new request on the same image (I think content is not well displayed), pagespeed thrown a new process that should last 5 seconds or less, and sometimes never end (killed by FCGID). And so on on each try ...
it should happened on getting the cached image or when creating the cached image

Greatings,
Eric
Version: 13: on
Filters
cw	Collapse Whitespace
gp	Convert Gif to Png
jp	Convert Jpeg to Progressive
jw	Convert Jpeg To Webp
pj	Convert Png to Jpeg
hw	Flushes html
ci	Inline Css
io	In-place optimize for browser
js	Jpeg Subsampling
rj	Recompress Jpeg
rp	Recompress Png
rw	Recompress Webp
rc	Remove Comments
cf	Rewrite Css
jm	Rewrite External Javascript
jj	Rewrite Inline Javascript
cp	Strip Image Color Profiles
md	Strip Image Meta Data
Options
EnableCachePurge (euci)             False
EnableRewriting (e)                 1
FileCacheCleanIntervalMs (afcci)    3600000
FileCacheInodeLimit (afcl)          500000
FileCachePath (afcp)                /var/cache/mod_pagespeed/
FileCacheSizeKb (afc)               4096000
ImplicitCacheTtlMs (ict)<PHONE_NUMBER>0
InPlaceResourceOptimization (ipro)  True
LoadFromFileCacheTtlMs (lfct)<PHONE_NUMBER>0
LogDir (ald)                        /var/log/pagespeed
RewriteLevel (l)                    Optimize For Bandwidth
SslCertDirectory (assld)            /etc/ssl/certs
StatisticsLogging (asle)            True

the size of the file is not good : less than the size of original and rewrited images.

Are you saying that according to Apache logs, when a request gets into this "waiting for completion of url" state, that it (a) does serve out a response and (b) the bytes in the response are >0 but less than original or optimized?  That's very surprising, but if that's what's happening then it's also very good debugging information.

Hello,
Yes, it's with IPRO. limited to some image folder (no css/js ..) only jpg (more than 90%), gif, and png. There is some PDF but they are not rewritten.
Warning messages always occure to jpg (thus there is a few gif with very hight hits).
Yes, (a) a response is given (status 200 in apache access log), (b) the size is > 0 but < to size of original and rewrited images (far from ).
Greatings,
Eric

One example :`
File sizes :
Original :
1944696 déc.  20  2012 coucher_soleil_surf_casting_plage_de_vert_bois.jpg
Resized :
252359 mai   12 05:23 xcoucher_soleil_surf_casting_plage_de_vert_bois.jpg.pagespeed.ic.3yu50AYt9t.webp,
689914 mai   12 03:44 xcoucher_soleil_surf_casting_plage_de_vert_bois.jpg.pagespeed.ic.o9Im1AbLI-.jpg,
382387 mai   12 03:43 xcoucher_soleil_surf_casting_plage_de_vert_bois.jpg.pagespeed.ic.oSN3mSp6D3.webp,
431269 mai   12 07:50 xcoucher_soleil_surf_casting_plage_de_vert_bois.jpg.pagespeed.ic.XKOxTrFFXo.jpg,
Apache access log (the same user - sameip - that I think try to reload image):
sameip - - [12/May/2015:11:14:35 +0200] "GET /IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg HTTP/1.1" 200 94384 "-" "Mozilla/5.0 (Linux; Android 4.4.4; SM-G316HU Build/KTU84P) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/<IP_ADDRESS> Mobile Safari/537.36 GSA/<IP_ADDRESS>7016.arm"
sameip - - [12/May/2015:11:20:43 +0200] "GET /IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg HTTP/1.1" 200 80504 "-" "Mozilla/5.0 (Linux; Android 4.4.4; SM-G316HU Build/KTU84P) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/<IP_ADDRESS> Mobile Safari/537.36 GSA/<IP_ADDRESS>7016.arm"
sameip - - [12/May/2015:11:22:36 +0200] "GET /IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg HTTP/1.1" 200 101324 "-" "Mozilla/5.0 (Linux; Android 4.4.4; SM-G316HU Build/KTU84P) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/<IP_ADDRESS> Mobile Safari/537.36 GSA/<IP_ADDRESS>7016.arm"
sameip - - [12/May/2015:11:28:36 +0200] "GET /IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg HTTP/1.1" 200 92996 "-" "Mozilla/5.0 (Linux; Android 4.4.4; SM-G316HU Build/KTU84P) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/<IP_ADDRESS> Mobile Safari/537.36 GSA/<IP_ADDRESS>7016.arm"
sameip - - [12/May/2015:11:30:25 +0200] "GET /IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg HTTP/1.1" 200 95772 "-" "Mozilla/5.0 (Linux; Android 4.4.4; SM-G316HU Build/KTU84P) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/<IP_ADDRESS> Mobile Safari/537.36 GSA/<IP_ADDRESS>7016.arm"
sameip - - [12/May/2015:11:32:22 +0200] "GET /IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg HTTP/1.1" 200 102712 "-" "Mozilla/5.0 (Linux; Android 4.4.4; SM-G316HU Build/KTU84P) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/<IP_ADDRESS> Mobile Safari/537.36 GSA/<IP_ADDRESS>7016.arm"
And some of the warnings (there are multi task number because user try to reload the image, and new process are thrown) :
[Tue May 12 11:30:02 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14266] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 75.247 sec
[Tue May 12 11:30:02 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14068] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 435.955 sec
[Tue May 12 11:30:05 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @13871] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 551.309 sec
[Tue May 12 11:30:07 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14266] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 80.267 sec
[Tue May 12 11:30:07 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14068] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 440.955 sec
[Tue May 12 11:30:10 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @13871] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 556.309 sec
[Tue May 12 11:30:12 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14266] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 85.274 sec
[Tue May 12 11:30:12 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14068] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 445.956 sec
[Tue May 12 11:30:17 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14266] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 90.275 sec
[Tue May 12 11:30:17 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14068] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 450.956 sec
[Tue May 12 11:30:22 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14266] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 95.275 sec
[Tue May 12 11:30:22 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14068] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 455.956 sec
[Tue May 12 11:30:27 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14266] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 100.275 sec
[Tue May 12 11:30:32 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14266] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 105.276 sec
[Tue May 12 11:30:37 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14266] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 110.276 sec
[Tue May 12 11:30:40 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14554] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 5 sec
[Tue May 12 11:30:42 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @14266] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg for 115.276 sec
Eric

Thanks!
Could you paste your LogFormat?  Are you using %B to report response sizes?

here it is :
LogFormat "%h %l %u %t "%r" %>s %O "%{Referer}i" "%{User-Agent}i"" combined

Thanks!  So this is bytes sent as reported by %O.
This is really helpful; still debugging.

Here one apache access with good file size :
[12/May/2015:16:40:46 +0200] "GET /IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg HTTP/1.1" 200 382516 "http://www.google.fr/imgres?imgurl=http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg&imgrefurl=http://www.opalesurfcasting.net/peche_en_surf_casting_mot173.html&h=1704&w=2272&tbnid=SlsuVIADL7HKvM:&zoom=1&tbnh=94&tbnw=125&usg=__fR10g3-pvf-gTfTaQWIi-dcmqzA=&docid=XyKIkjG7qctOwM" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.135 Safari/537.36"
382516 = ~ 382387
xcoucher_soleil_surf_casting_plage_de_vert_bois.jpg.pagespeed.ic.o9Im1AbLI-.jpg,
382387 mai 12 03:43
and the same request ten seconds later with bad file size
[12/May/2015:16:40:56 +0200] "GET /peche_en_surf_casting_mot173.html HTTP/1.1" 200 105654 "http://www.google.fr/imgres?imgurl=http://www.opalesurfcasting.net/IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg&imgrefurl=http://www.opalesurfcasting.net/peche_en_surf_casting_mot173.html&h=1704&w=2272&tbnid=SlsuVIADL7HKvM:&zoom=1&tbnh=94&tbnw=125&usg=__fR10g3-pvf-gTfTaQWIi-dcmqzA=&docid=XyKIkjG7qctOwM" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.135 Safari/537.36"
For the same user (same ip)

382516 = ~ 382387

This is expected because %O includes headers

the same request ten seconds later with bad file size

That second request is for /peche_en_surf_casting_mot173.html, not /IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg.
but the examples above for /IMG/coucher_soleil_surf_casting_plage_de_vert_bois.jpg are good.

IPRO has several internal states.  If I'm reading your logs right this is happening during the third (serve optimized resource) state.

It looks like we should be logging errors on failed ap_rwrite calls, though this wouldn't cause the problem.

Sorry for my "bug"

IPRO has several internal states. If I'm reading your logs right this is happening during the third >(serve optimized resource) state.
It's happened in the first state too when first rewrite a non yet rewrited image.
For the third state it's look like trying to rewrite thus rewrited image is in cache.
This seem to occure more often when rewriting webp images (the images I check are at least 9/10 webp requests) .

Another case :
Image is not rewrited in cache yet. Then one mod_pagespeed thread is launched waiting for completion of url.
Before browser image call :
Image in cache (only one jpg) :
528965 mai   12 05:37 xquiberville-plage-est.jpg.pagespeed.ic.o1gRWLsmzT.jpg,
image is asked by browser but no log in apache access log (nothing has been sent yet) :
last apache access log for this image :
[12/May/2015:05:37:42 +0200] "GET /IMG/quiberville-plage-est.jpg HTTP/1.1"<PHONE_NUMBER> "-" "msnbot-media/1.1 (+http://search.msn.com/msnbot.htm)"
mod_page speed start to send "warning - waiting for completion of URL" :
one message every 5 seconds:
the last one :
[mod_pagespeed <IP_ADDRESS>-4448 @11818] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 411.224 sec
Then a log is send to apache access log with status 200 send :
[12/May/2015:19:02:08 +0200] "GET /IMG/quiberville-plage-est.jpg HTTP/1.1" 200 341728 "https://www.google.fr/" "Mozilla/5.0 (Linux; Android 4.4.2; fr-fr; SAMSUNG GT-I9195/I9195XXUCNK1 Build/KOT49H) AppleWebKit/537.36 (KHTML, like Gecko) Version/1.5 Chrome/28.0.1500.94 Mobile Safari/537.36"
and one more file is cached (a webp image) :
247995 mai   12 19:09 xquiberville-plage-est.jpg.pagespeed.ic.e7-jnTX07F.webp,
528965 mai   12 05:37 xquiberville-plage-est.jpg.pagespeed.ic.o1gRWLsmzT.jpg,
But the bytes send are not the attended size from cached files or original one :
1418629 déc.  20  2012 /home/opalesurfcasting/public_html/IMG/quiberville-plage-est.jpg
Note the user agent is still from a webp able browser.
This is on First state (with loadfromfile so no http fetch).
Greatings,
Eric

Testing now, I see http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg as 330170 bytes consistently, which is compatible with the 341728 you saw in the access log, and doesn't indicate truncation.  It's interesting that the one you're seeing in the https cache on disk is 247995, substantially smaller, and I can't see where this would come from.

Hello,
It's because a third rewrited image has been added.
I have now :
247995 mai   12 19:09 xquiberville-plage-est.jpg.pagespeed.ic.e7-jnTX07F.webp,
528965 mai   12 20:32 xquiberville-plage-est.jpg.pagespeed.ic.o1gRWLsmzT.jpg,
330421 mai   12 20:34 xquiberville-plage-est.jpg.pagespeed.ic.tRs1Xq-Dbj.webp,
I look in access log and error log.
Eric

528965 mai 12 20:32 xquiberville-plage-est.jpg.pagespeed.ic.o1gRWLsmzT.jpg,
has been rewrited (modification time ls -al) because I removed a folder from mod_pagespeed and restart apache. (I don't understand why images are rewritted as soon as apache is restarted)

I think those are your access log :
24 - - [12/May/2015:20:32:44 +0200] "GET /IMG/quiberville-plage-est.jpg HTTP/1.1" 200 383720 "-" "curl/7.35.0"
24 - - [12/May/2015:20:32:57 +0200] "GET /IMG/quiberville-plage-est.jpg HTTP/1.1" 200 529038 "-" "curl/7.35.0"
24 - - [12/May/2015:20:33:50 +0200] "GET /IMG/quiberville-plage-est.jpg HTTP/1.1"<PHONE_NUMBER> "-" "Chrome/100"
24 - - [12/May/2015:20:34:19 +0200] "GET /IMG/quiberville-plage-est.jpg HTTP/1.1" 200 330494 "-" "Chrome/100"
24 - - [12/May/2015:20:34:43 +0200] "GET /IMG/quiberville-plage-est.jpg HTTP/1.1" 200 330494 "-" "Chrome/100"
24 - - [12/May/2015:20:35:06 +0200] "GET /IMG/quiberville-plage-est.jpg HTTP/1.1" 200 330494 "-" "Chrome/100"
I remove the last one for url parameters

They are there :
[Tue May 12 20:32:49 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17834] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 5.017 sec
[Tue May 12 20:33:02 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17805] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 5 sec
[Tue May 12 20:33:07 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17805] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 10.006 sec
[Tue May 12 20:33:12 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17805] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 15.012 sec
[Tue May 12 20:33:17 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17805] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 20.012 sec
[Tue May 12 20:33:22 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17805] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 25.012 sec
[Tue May 12 20:33:55 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17941] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 5 sec
[Tue May 12 20:34:00 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17941] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 10.018 sec
[Tue May 12 20:34:05 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17941] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 15.018 sec
[Tue May 12 20:34:24 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17564] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 5.001 sec
[Tue May 12 20:34:48 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17564] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 5 sec
[Tue May 12 20:35:11 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @17957] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/quiberville-plage-est.jpg for 5.009 sec
Thread 17941 seems to be the one that create the smallest webp.
Then it should be served to thread 17564 and 17957.

@jeffkaufman shot in the dark:
https://github.com/pagespeed/mod_pagespeed/blob/master/pagespeed/apache/mod_instaweb.cc#L759 ignores a return value that is being used meaningfully:
https://github.com/pagespeed/mod_pagespeed/blob/master/pagespeed/system/in_place_resource_recorder.cc#L115

@jeffkaufman please ignore my comment, that code path looks  fine to me

Hello,
I have been able to reproduce it : bad file size, long "waiting for completion of URL", and image well rewrited in cache.
I go further to validate checks :

with no image cached for the type to be served accordingly to the browser request header
with image yet in cache for the type to be served accordingly to the browser request header

Greatings,
Eric

This is great that you've been able to reproduce that.  Does that mean that
100% of the time you fetch a particular file from your server, a new thread
gets trapped in a "waiting for completion" loop?
I know you said earlier that you mailed your config to Jeff, but I don't
have it.  Can you specify for me?

What other Apache modules do you have enabled?
Are you using memcached?  If so, are there other servers (e.g. haproxy)
between apache and the memcached?
If you are not using memcached, what are you using as the file system
for your file-cache?  Is it a local hard disk?  Or something
network-mounted?
Do you have LoadFromFile enabled?

Thanks,
-Josh
On Tue, May 12, 2015 at 7:46 PM, eldk<EMAIL_ADDRESS>wrote:

Hello,
I have been able to reproduce it : bad file size, long "waiting for
completion of URL", and image well rewrited in cache.
I go further to validate checks :

with no image cached for the type to be served accordingly to the
browser request header
with image yet in cache for the type to be served accordingly to the
browser request header

Greatings,
Eric
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-101461506
.

Hello,
1 - I send you and @jeffkaufman the list of apache modules used now.
2 - no, I'm not using memcached
3 - The file system cache is on local hard disk
4 - The first error message occur with httpfetch of original image, but I've moved to LoadFromFile now. I think that's this suppress one cycle to rendering rewrited image ?
Try now to reproduce it again.
Thanks,

Ok,
1 -  rm all rewrited files from cache for one image
2 - open chrome dev tools with cache disable and modify bandwidth in adaptive view to a slow connection (I use GPRS 50kbps 500ms)
3 - check if nothing has been rewrited for the image choosen
4 - launch load in Chrome with choosen image URL
5 - cancel the load
a - mod_pagespeed start to give warnings in error log " waiting for completion of URL for " a lot as load is slow.
b - file size reported in apache access log is the amount of bytes send until the load was canceled.
c - I can't stat how to evaluate how fast it is for the moment, but the rewrited is well done each time (less than a second) and I think the time to do it is not as long as sending image to client browser.
So this is, I think not a bug, but a "missconception" in how are handled (if it can be) the warnings when the sending is long due to client, bandwidth usage or maybe other sources.
So for the warning messages that are less than 2 messages and are 1 or 2 warning when sending image to client (the numerous "warning waiting for completion") maybe have the same sources :

bandwidth ability and usage to send the image to the client
bandwidth ability and usage from the client to load image

Should you check ?
Greatings,
Eric

@eldk: Here's a hypothesis:

The "waiting for completion of url" message means that there's a request that's still in progress
You're simulating low bandwidth with "GPRS 50kbps 500ms" and your server also has low bandwidth normally
So large transfers take a long time, more than the 5s trigger for the "waiting for completion" message
The file size is low when the browser cancels the slow load and you have a partial transfer.

This I should be able to reproduce locally, and I'll see if that's really how our system acts.

Hello,

The "waiting for completion of url" message means that there's a request that's still in progress
So, but if a slow client is pushing a request : numerous warnings are produced. Thus there is not really something to warn (except if the rewrite image process is not well closed).

The numerous 5 s one message only and sometimes 10 s second messages happened also when bandwidth output usage is low , for my case between 1 am and 5 am (GMT+2) -
So I think maybe it's a "false warning" message or some process - before sending image - is not closed at the proper time.
rewrite -> send
not rewrite->send
errors before send then errors after rewrite|not rewrite
Thanks,
Eric

@eldk When I try to reproduce this locally with chrome set to very low bandwidth I see the pagespeed code finishing very quickly, and then apache slowly sending out the bytes.  I need to figure out what's different about your situation that seems to make the writing back up into PageSpeed.

Same non-reproducing behavior with curl:
curl -o /dev/null http://localhost:8080/mod_pagespeed_example/images/Puzzle.jpg --limit-rate 5000

It downloads slowly, but it's all handled by Apache after PageSpeed.

I think to test this I need to figure out how to get Apache into a mode where instaweb_in_place_filter will see multiple buckets.  Right now even large files (241k) seem to come in as a single bucket.

Maybe generate the file with php script that flushes?
On May 13, 2015 8:56 AM, "Jeff Kaufman"<EMAIL_ADDRESS>wrote:

I think to test this I need to figure out how to get Apache into a mode
where instaweb_in_place_filter will see multiple buckets. Right now even
large files (241k) seem to come in as a single bucket.
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-101654144
.

I don't think this is the problem, but looking at instaweb_in_place_filter I don't think it's quite right.  It needs to be prepared to be called multiple times, in case it's processing output from something that's intermittent, but the handling of first and calling ConsiderResponseHeaders looks like it expects to be called only once.  Specifically, recorder->ConsiderResponseHeaders() could be called on each bucket brigade instead of only on the first one.
This was added by @morlovich in
https://github.com/pagespeed/mod_pagespeed/commit/051b2f91a15b6f1acba8e551e85750e51df5bc96#diff-f315ba73469d44612ff2edcef2c1ce64 , but I don't see how it could be causing the current problem.

Hello,
I haven't try to reproduce it with Firefox.
But for the message that are repeted many times from 5s to x s, I notice that the UA is always (9/10 maye more)for chrome and/or safari.
@jeffkaufman so perhaps this is the reason that it can't be reproduce with CURL.
Nothing to do with preload and optimization from browser ?
https://groups.google.com/forum/#!topic/mod-pagespeed-discuss/Fh-phRTPBP8

If you go there :
http://www.loband.org/loband/simulator.jsp and have a try in firefox.
1 - you have only messages when image is rewrited (not exist in the cache)
2 - when image is yet rewrited : no message at all
and do the try with Chrome and low bandwith :
1 - messages are there where the image is rewrited
2 - messages are there if the image has yet been rewrited and is in cache.

To test instaweb_in_place_filter on being called multiple times I set up my Apache config as:
ProxyPass /proxy http://www.jefftk.com
ProxyPassReverse /proxy http://www.jefftk.com

And then looked at localhost:8080/proxy/test/quiberville-plage-est.jpg?cachebuster=somethingrandom
This did make Apache work over multiple buckets, calling instaweb_in_place_filter repeatedly, but even with --limit-rate all the buckets first move through PageSpeed's instaweb_in_place_filter and so also ApacheFetch quickly before slowly being sent out to the browser.

I've set an outgoing bandwidth limit on http://www.jefftk.com/test*, but I'm seeing Done() called on the ApacheFetch called almost immediately, before all the data gets to the client.
I'm also seeing what might be the same bug or might be different.  To reproduce:

Set up PageSpeed as proxying, as shown above
start fetching localhost:8080/proxy/test/quiberville-plage-est.jpg?a=somethingrandom
kill the fetch after it's partially downloaded
fetch it again
observe that you receive a truncated file
in fact, the cache is poisoned with this truncated file, and we'll serve it out every time

I haven't found the culprit in the code yet, but it sounds like we're recording into our cache as if we've done things successfully when we should be aborting the recording.

That sounds like we're ignoring a Done(false) (or not producing one!)
On Wed, May 13, 2015 at 10:40 AM, Jeff Kaufman<EMAIL_ADDRESS>wrote:

I've set an outgoing bandwidth limit on http://www.jefftk.com/test*, but
I'm seeing Done() called on the ApacheFetch called almost immediately,
before all the data gets to the client.
I'm also seeing what might be the same bug or might be different. To
reproduce:

Set up PageSpeed as proxying, as shown above
start fetching
localhost:8080/proxy/test/quiberville-plage-est.jpg?a=somethingrandom
kill the fetch after it's partially downloaded
fetch it again
observe that you receive a truncated file
in fact, the cache is poisoned with this truncated file, and we'll
serve it out every time

I haven't found the culprit in the code yet, but it sounds like we're
recording into our cache as if we've done things successfully when we
should be aborting the recording.
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-101690973
.

Also perhaps instaweb_in_place_filter might be missing come cases to call
recorder->Fail?
On Wed, May 13, 2015 at 10:45 AM, Maksim Orlovich<EMAIL_ADDRESS>wrote:

That sounds like we're ignoring a Done(false) (or not producing one!)
On Wed, May 13, 2015 at 10:40 AM, Jeff Kaufman<EMAIL_ADDRESS>wrote:

I've set an outgoing bandwidth limit on http://www.jefftk.com/test*, but
I'm seeing Done() called on the ApacheFetch called almost immediately,
before all the data gets to the client.
I'm also seeing what might be the same bug or might be different. To
reproduce:

Set up PageSpeed as proxying, as shown above
start fetching
localhost:8080/proxy/test/quiberville-plage-est.jpg?a=somethingrandom
kill the fetch after it's partially downloaded
fetch it again
observe that you receive a truncated file
in fact, the cache is poisoned with this truncated file, and we'll
serve it out every time

I haven't found the culprit in the code yet, but it sounds like we're
recording into our cache as if we've done things successfully when we
should be aborting the recording.
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-101690973
.

Looking at the apache code, I don't currently see anyway for instaweb_in_place_check_headers_filter to know that the request got aborted by the user and so should not be cached.
Separately, it's minorly wrong that instaweb_in_place_check_headers_filter expects that there can only be one EOS bucket.  There should be, but "ignore any buckets after the first EOS bucket" is something all modules are supposed to do.

Debugging this I found Issue 1078

Hello,
I've disabled  :
-jw	Convert Jpeg To Webp
-io	In-place optimize for browser

rw	Recompress Webp

And wait to see if long lasting warning messages still occure except on first cache write.

With those 3 options disabled.
Warning messages appears only when optimized jpg is created and should last. After that, no more warnings for Firefox nor Chrome.
I don't know why but every time apache is restarted, cached image are regenerated. I don't know why this behavior. I'd prefer that images that have yet been cached are used again, even if apache is restarted. Is it a feature ?
Thanks,
Eric

I don't know why but every time apache is restarted, cached image are regenerated. I don't know why this behavior. I'd prefer that images that have yet been cached are used again, even if apache is restarted.

This one I understand!  You have an explicitly configured shared memory metadata cache (shmmc)  enabled.  By default there's a shmmc that is write-through, which means writes are slower because they have to go to disk but they also persist across restarts.  If you enable one with explicit configuration, as you have, then we turn off write-through for faster writes but we lose persistence.
Yes, this is confusing (though it is documented) and I have a draft change to fix it up that switches us to only write cache snapshots to disk.  But that draft change is stuck behind fixing this bug and a couple others.

This one I understand! You have an explicitly configured shared memory metadata cache (shmmc) enabled. By default there's a shmmc that is write-through, which means writes are slower because they have to go to disk but they also persist across restarts. If you enable one with explicit configuration, as you have, then we turn off write-through for faster writes but we lose persistence.

Ok, that was the rname folder that have disappeared.
So disabling shmmc will give persistance. Now I understand too. On restart, apache frees memory.
Thanks.

Hello,
I've disabled ModPagespeedCreateSharedMemoryMetadataCache and enabled convert_jpeg_to_webp,recompress_webp,in_place_optimize_for_browser again.
Thank you,
Eric

And It's really better :
jpg images are now rewrited only one time when they are not in the cache.
After being rewrited to webp, every request is served with the cached image.
So I think there it is another bug : "when ModPagespeedCreateSharedMemoryMetadataCache is used, a jpg to webp conversion is thrown on every request".
I don't know if memcached should change this, but this is another case.

when ModPagespeedCreateSharedMemoryMetadataCache is used, a jpg to webp conversion is thrown on every request

Could you say more about this?  What about your current setup was telling you it was making webp conversions every time?

Hello,
I've disabled ModPagespeedCreateSharedMemoryMetadataCache.
And now on second access and later (Third (optimized resource in cache)), to a still cached image in webp, I have no more "waiting for completion ..."  long messages that last  more than 2 messages/image .This morning for an image accessed more than 20 times, after it has been rewrited, I have only one time two warning messages .
Before, with ModPagespeedCreateSharedMemoryMetadataCache enabled,  it was more than 9/10 access that throw "waiting ..."  long messages,  more than 2 messages/image as it was rewriting it (Third (optimized resource in cache)).  This occured only with webp image.
->Is ModPagespeedCreateSharedMemoryMetadataCache enabled ;
YES ->are we in Third state (optimized resource in cache) : yes -> should we send a webp image : yes->send and throw a long sequence of "Warning ..." as if you are rewriting image thus it's in cache (more than 9/10).
->Is ModPagespeedCreateSharedMemoryMetadataCache enabled ;
NO->are we in Third state (optimized resource in cache) : yes -> should we send a webp image : yes-> Send the webp image and throw max 2 warning message sequence on some circonstances (less than 1/10 sending)
thanks,
Eric

CASE C
->Is ModPagespeedCreateSharedMemoryMetadataCache enabled ;
NO->are we in Third state (optimized resource in cache) : yes->-> should we send a webp image : NO->Send  the jpg image and throw 4 warnings.
Circunstances :
UA -Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; InfoPath.2)
Client connexion : supposed to be slow (I've a lot  of visitors from low-bandwith country - 25%)
Time image served :
low-bandwith-ip - - [14/May/2015:14:11:37 +0200] "GET /IMG/truite_et_saumon_atlantique.jpg HTTP/1.1" 200 506653 "http://www.bing.com/images/search?q=LE+POISSON+SAUMON&qs=ds&form=QBIR" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; InfoPath.2)"
Error logs :
[Thu May 14 14:11:42 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @27928] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/truite_et_saumon_atlantique.jpg for 5.009 sec
[Thu May 14 14:11:47 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @27928] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/truite_et_saumon_atlantique.jpg for 10.128 sec
[Thu May 14 14:11:52 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @27928] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/truite_et_saumon_atlantique.jpg for 15.134 sec
[Thu May 14 14:11:57 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @27928] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/truite_et_saumon_atlantique.jpg for 20.134 sec
Images in cache :
506530 mai   14 10:09 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.3xrlA59JejXVZ89m41dU.jpg,
348170 mai   14 04:27 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.Bejme5ak9LXVZ89m41dU.jpg,
307837 mai   14 09:44 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.q-FNdkJK56XVZ89m41dU.webp,
393479 mai   14 03:36 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.T5NGePK7znXVZ89m41dU.webp,

CASE D
->Is ModPagespeedCreateSharedMemoryMetadataCache enabled ;
NO->are we in Third state (optimized resource in cache) : yes->-> should we send a webp image : yes-> send the webp image-> is the load cancelled, stopped before complete load of image : yes-> sending is not killed and throw a bunch of  warnings until process is killed by FCGID .
Circunstances :
iPhone; CPU iPhone OS 8_3 like Mac OS X) AppleWebKit/600.1.4 (KHTML, like Gecko) GSA/5.2.43972 Mobile/12F70 Safari/600.1.4
Client connexion : GPRS/3G/4G or wifi (guess from ip)
Time image served :
ip - - [14/May/2015:16:03:25 +0200] "GET /IMG/truite_et_saumon_atlantique.jpg HTTP/1.1" 200 186792 "-" "Mozilla/5.0 (iPhone; CPU iPhone OS 8_3 like Mac OS X) AppleWebKit/600.1.4 (KHTML, like Gecko) GSA/5.2.43972 Mobile/12F70 Safari/600.1.4"
Begin of warnings :
[Thu May 14 16:03:31 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @2888] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/truite_et_saumon_atlantique.jpg for 5 sec
End of warnings :
[Thu May 14 16:10:07 2015] [warn] [mod_pagespeed <IP_ADDRESS>-4448 @2888] Waiting for completion of URL http://www.opalesurfcasting.net/IMG/truite_et_saumon_atlantique.jpg for 401.066 sec
Images in cache :
Last modification time :
506530 mai   14 10:09 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.3xrlA59JejXVZ89m41dU.jpg,
348170 mai   14 04:27 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.Bejme5ak9LXVZ89m41dU.jpg,
307837 mai   14 09:44 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.q-FNdkJK56XVZ89m41dU.webp,
393479 mai   14 03:36 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.T5NGePK7znXVZ89m41dU.webp,
Last access time :
506530 mai   14 10:34 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.3xrlA59JejXVZ89m41dU.jpg,
307837 mai   14 09:45 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.q-FNdkJK56XVZ89m41dU.webp,
348170 mai   14 06:10 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.Bejme5ak9LXVZ89m41dU.jpg,
393479 mai   14 03:36 xtruite_et_saumon_atlantique.jpg.pagespeed.ic.T5NGePK7znXVZ89m41dU.webp,

As what I see now, case D is the first big concern :
On heavy load more and more cancelled requests and more and more waiting + cache in construction.
Things are degrading rapidly + legally hotlinked images with timeout  + human cancelled load ...
I will try to build the cache this night from local requests.

Hello,
The image cache  is still building, I do it slowly. But things are better, less canceled image request (direct access to fullsized image) and a bunch less of warnings.
I think that with #1081 it will be perfect.
Thank you,
Eric

Ok: I think I understand this now.  There are two cases where we'll emit this message, one mostly benign and the other because of a kernel bug.

When your cache is slow to respond (slow memcached, file cache on nfs) PageSpeed will temporarily print out Waiting for completion of URL messages.  To fix this, move your cache to tmpfs or figure out how to get your memcached server to be more responsive.
If you're running a linux kernel that has https://github.com/torvalds/linux/commit/b0c29f79ecea0b6fbcefc999e70f2843ae8306db but not https://github.com/torvalds/linux/commit/76835b0ebf8a7fe85beb03c75121419a7dec52f0 then there's a race condition in the linux futex code that underlies our condition variables, where even though the code correctly signals us the kernel keeps us waiting.  In this case PageSpeed will permanently [1] print out Waiting for completion of URL messages.  To fix this, upgrade your kernel.

More discussion about the futex issue: https://groups.google.com/forum/#!topic/mechanical-sympathy/QbmpZxp6C64 and https://news.ycombinator.com/item?id=9542548 .  It seems like it's most common on Haswell processors, though people have seen it on others.
[1] I think in some cases (not stock apache) people have modules that will clean up threads if they get stuck and take too long, so you might only see these messages for two minutes or something.

@Cyriltra what is your kernel version? can you paste the output of uname -a

Offline discussion with @jmaessen: the ApacheFetch::Wait() code is probably not vulnerable to the futex bug because of the way it uses TimedWait and looping.  We do have other places where we use ordinary Wait, though, which are vulnerable.  For example, Worker::WorkThread::GetNextTask calls Wait to wait for there to be some work on its queue, and if that doesn't wake up then our callbacks will never run and we'll get stuck here.

There are two cases where we'll emit this message, one mostly benign and the other because of a kernel bug.

Looking at people's reports and looking into which systems have the kernel bug there are some systems that don't have the bug that do get stuck indefinitely on Waiting for completion of URL.  All of these are using memcached, so I'm going to look deeper into that code.

Same problem here.
We use pagespeed from 2012 and we are experiencing problem form the last 5 days.
We made an update of all the system (yum update) and after it something is change.. We use the last version of pagespeed with memcached and from this update all the server become instable.
This is how our server dies after the last update.

We don't use nothing of this:

admin-page handling (which I think is not at issue here based on the log
messages)
ModPagespeedInPlaceResourceOptimization (on by default starting in 1.9)
ModPagespeedMapProxyDomain

and after this problem we tried to insert
ModPagespeedInPlaceResourceOptimization Off
but nothing change.
Every little rewrite now ask for a lot of CPU and at the moment we set Off Pagespeed for about 90% of the sites (97 total sites on the server).
The error in the log are the same of the others users. The main problem is the CPU high load but also a problem with memcached. With the begin of this problems also memcached start to have problem with a lot of message like this:
aprMemCache::Put error: Could not find specified socket in poll list
I tried to remove the last stable version and reinstall the last 1.8.x stable but the problem persist.
I also tried to reinstall Apache 2.2, memcached, apc and all the "components" of the webserver.
I'm not expert but i think that is a bug related with kernel or with a library or similar the it use for the rewriting.
We use CentOS release 6.6 (Final) 2.6.32-504.16.2.el6.x86_64
Thanks for any helping infos and excuse me for my english :)
I hope to find a solution because before this problem, as you can see in the attachment, the Server was very fast and stable. It never use more than 50% of the CPU but now is always at 100%.
Bye

Hello,
I think you should check first that memcached is running and if running push a "echo stats | nc ip port"
I think that you should check your memcached conf  :  ip, port, user.
Your mod_pagespeed.conf for memcached configuration : ip:port
Eric

Hi eldk,
memcached is working fine.
It is working and mod pagespeed is properly configurated:
ModPagespeedMemcachedServers <IP_ADDRESS>:11211
ModPagespeedMemcachedTimeoutUs 50000
ModPagespeedMemcachedThreads 1

This is the echo of memcached stats:
Every 2,0s: echo stats | nc <IP_ADDRESS> 11211                                                                                Sun May 31 14:12:33 2015
STAT pid 22027
STAT uptime 42988
STAT time<PHONE_NUMBER>
STAT version 1.4.22
STAT libevent 2.0.22-stable
STAT pointer_size 64
STAT rusage_user 12.063166
STAT rusage_system 33.538901
STAT curr_connections 66
STAT total_connections 2771
STAT connection_structures 169
STAT reserved_fds 20
STAT cmd_get 153577
STAT cmd_set 65655
STAT cmd_flush 0
STAT cmd_touch 0
STAT get_hits 83218
STAT get_misses 70359
STAT delete_misses 0
STAT delete_hits 0
STAT incr_misses 0
STAT incr_hits 0
STAT decr_misses 0
STAT decr_hits 0
STAT cas_misses 0
STAT cas_hits 0
STAT cas_badval 0
STAT touch_hits 0
STAT touch_misses 0
STAT auth_cmds 0
STAT auth_errors 0
STAT bytes_read 676621121
STAT bytes_written<PHONE_NUMBER>
It was configured long time ago and only in the last 5 days starts having problems.
As you can see in the cpu graph only from 27/may 14pm all the system start using a lot of cpu.
Before the 27/5 nothing change, memcached was configured 2 year ago and always working and pagespeed too.
When we disabling Pagespeed all the system work fine with no cpu peak but we don't understand what's changend.
We made the update of all the system the 30/apr but we think (we aren't sure) that system restart and httpd restart was excuted only the 27/may when problem starts.
Thanks

Hello @jeffkaufman ,
Since my first tries, I have migrated to a more powered server : more cpu, ram and bandwith (100 Mbps).
I monitored all "waiting for completion ..." messages, and it seems to occur only on "canceled" download (partial send of file) - 99,9 % : pictures (the more large ones), some "big" js.
I have tried and monitor apache2.3/fgcid/mpm-prefork and apache2/fcgid/mpm-worker with our without memcached (2.0.24-stable).
All my pages are php generated and cached before (for some one's a day, for over one's a week ...) mod_pagespeed get them and served them to visitors - so the server ressources used are even less of 5% average (top).
Thanks,
Eric

Hello @capn3m0 ,
have you tried to disable memcached for mod_pagespeed ?
Eric

Yes we try
Memcached On for Pagespeed | Memcached Daemon On
Memcached Off for Pagespeed | Memcached Daemon On (for other apps that use it)
Memcached Off for Pagespeed | Memcached Daemon Off
but nothing change.

I made some tests and maybe i found who is causing all this troubles: MMAP.
I'm not expert but disabling MMAP in Apache adding this in httpd.conf:
EnableMMAP off
a part of my problem are solved. No more cpu peak and general high cpu load.
I has downgraded mod pagespeed to 1.7.30 and for about 1 hour all the system was stable with pagespeed (finally) On.
After i tried the last <IP_ADDRESS> but cpu and error "Waiting for completion of
URL http://exampledomain.com/example-slug/" starts again.
Now i downgraded to <IP_ADDRESS> and system is stable, no high cpu and no "Waiting for completion.."
Remains some problem related to Memcached like this kind of error:
AprMemCache::Put error: Could not find specified socket in poll list. (70015)
but the system is stable and with pagespeed On.
I will investigate..
Someone can try if using "EnableMMAP off" in apache solve problem related to cpu high load?

capn3m0: this is some great detective work.  Thanks for your persistence.
We hadn't thought of this EnableMMAP issue and will check it out.
Note that InPlaceResourceOptimization existed in 1.8, and might be
vulnerable to the same problems as 1.9, but simply did not print a message
when it got stuck in that loop.  So the problem may be happening without a
message.
The AprMemCache issues may simply be timeout tuning issues. The default
timeout settings might not be appropriate for your setup, depending on
networking delays and whether you have mod_pagespeed communicating directly
with standard memcached, or whether you are using a proxy or something else
that speaks memcached protocol.
Thanks!
-Josh
On Sun, May 31, 2015 at 6:45 PM, capn3m0<EMAIL_ADDRESS>wrote:

I made some tests and maybe i found who is causing all this troubles: MMAP.
I'm not expert but disabling MMAP in Apache adding this in httpd.conf:
EnableMMAP off
a part of my problem are solved. No more cpu peak and general high cpu
load.
I has downgraded mod pagespeed to 1.7.30 and for about 1 hour all the
system was stable with pagespeed (finally) On.
After i tried the last <IP_ADDRESS> but cpu and error "Waiting for completion
of
URL http://exampledomain.com/example-slug/" starts again.
Now i downgraded to <IP_ADDRESS> and system is stable, no high cpu and no
"Waiting for completion.."
Remains some problem related to Memcached like this kind of error:
AprMemCache::Put error: Could not find specified socket in poll list.
(70015)
but the system is stable and with pagespeed On.
I will investigate..
Someone can try if using "EnableMMAP off" in apache solve problem related
to cpu high load?
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-107254703
.

2.6.32-504.16.2.el6.x86_64

This is the most current 2.6.32 kernel for 6.6, and I just looked at the source and verified that it is not vulnerable to the futex bug (get_futex_key_refs does have default: smp_mb(); /* explicit MB (B) */.  So it doesn't look like this is a kernel issue.

@capn3m0

We don't use nothing of this: ...

ModPagespeedInPlaceResourceOptimization (on by default starting in 1.9)

When you say you don't use ModPagespeedInPlaceResourceOptimization do you mean that when you upgraded to 1.9 you added ModPagespeedInPlaceResourceOptimization off to your config?  Otherwise you were actually running it: with the 1.9 upgrade we changed this feature from default-off to default-on.

@capn3m0

Someone can try if using "EnableMMAP off" in apache solve problem related to cpu high load?

Are you serving static files from NFS that might be edited elsewhere?  That's known to cause problems with mmap: http://httpd.apache.org/docs/2.2/misc/perf-tuning.html  (This is probably not it, but it's worth asking.)  There may also be things PageSpeed does differently when mmap is enabled, as a result of calling lower-level apache functions; I'll look into that.
And to confirm, EnableMMAP off fixed your high cpu usage issues, but it didn't fix your "waiting for completion of fetch" issues, right?

There may also be things PageSpeed does differently when mmap is enabled, as a result of calling lower-level apache functions; I'll look into that.

It looks like EnableMMAP (via conf->enable_mmap) controls only what happens when Apache needs to load a file into memory (file_bucket_read).  When PageSpeed needs to load files into memory, which it does when serving files from its cache, it uses its own file manipulations functions which don't consider enable_mmap.

Hi guys, any news about this bug?
I use the default mod_pagespeed configuration and sometimes I get the Waiting for completion of URL problem too...
How to fix? I didn't made any changes to the default mod_pagespeed config

Not yet, although we are working on a patch that will (a) help us debug it,
and (b) avoid typing up an Apache process indefinitely.
There are a number of workaround suggested depending on your config and
details about your symptoms.  Questions about your setup:

Do you use memcached?
If you use memcached, do you have a direct connection to it, or do
you go through a proxy?
If you are using a file-cache, is it on a local hard disk or a
remote-mounted one?
Do you use LoadFromFile directives?
Do you use MapProxyDomain directives?
What is your linux kernel version (there's a linux kernel futex bug
https://groups.google.com/forum/#!topic/mechanical-sympathy/QbmpZxp6C64
we suspect is involved in some cases)
What is your Apache MPM?
What other modules do you have installed (e.g. fcgi)?

Questions about your symptoms:

What sort of files are being reported in the WaitingForCompletion
messages?
Large ones only, or both large & small
Resources only, or also HTML?
Do your WaitingForCompletion messages keep going indefinitely (1 per
second) or does completion eventually occur?
What other error messages do you see in the logs?

On Thu, Jun 11, 2015 at 4:18 PM, giggioman00<EMAIL_ADDRESS>wrote:

Hi guys, any news about this bug?
I use the default mod_pagespeed configuration and sometimes I get the
Waiting for completion of URL problem too...
How to fix? I didn't made any changes to the default mod_pagespeed config
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-111264336
.

No

Page_speed use cache on local disk. And even the joomla cahce save the cached fle on local disk.

No

This directive doesn't appear under my pagespeed configuration, so I don't think

Linux 3.10.0-229.1.2.el7.x86_64

prefork

Any other modules

Images and pages link

I don't use large images on my site...

Images and pages link (for ecample: Hompage, category, etc, etc)

I get 3-4 messages per second

I get two other errors:

Could not create directories for file /var/cache/mod_pagespeed/*** (but permissions are right... I get this problem only when mod_pagespeed goes wild)
Fetch timed out:

Those directory creation errors are suspicious.  Could you be out of disk
space?  Or inodes?  Can you give more details on the permissions of
/var/cache/mod_pagespeed and what user the Apache children run as?
On Jun 11, 2015 5:05 PM, "giggioman00"<EMAIL_ADDRESS>wrote:

No
Page_speed use cache on local disk. And even the joomla cahce save
the cached fle on local disk.
No
This directive doesn't appear under my pagespeed configuration, so
I don't think
Linux 3.10.0-229.1.2.el7.x86_64
prefork

Any other modules
8.
Images and pages link
9. I don't use large images on my site...
10. Images and pages link (for ecample: Hompage, category, etc, etc)
11. I get 3-4 messages per second
12. I get two other errors:
1. Could not create directories for file
/var/cache/mod_pagespeed/*** (but permissions are right... I get this
problem only when mod_pagespeed goes wild)
2. Fetch timed out:
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-111277375
.

Nope, I'm not out of space... My VPS have 23.04 GB of total space but only 6 GB are used.
Spache childrn runs as: user
and permissions of /var/cache/mod_pagespeed are user:user
Usually I don't get this error. It appears only when appears the Waiting for completion of URL problem

Can you check if you are out of inodes?  Sometimes we run into
file-systems' inode limits before we run out of disk, but you can set our
inode-limit in the file-cache so we start deleting old cache entries to
reach the inode-target and the disk-space target.
df -i should tell you the number of inodes used and free on the file system.
This is probably a red herring but it's worth checking.  Something is
preventing you from doing file-cache operations that's normal works, and
you must be running out of something.  Could be open file-descriptors.
Could be i-nodes.  Not sure yet what else it could be.
Maybe run 'lsof (http://linux.die.net/man/8/lsof)' next time you see these
Waiting for Completion messages.
I can think of two things that would cause the Waiting For Completion
messages:

Some file-operation blocks indefinitely (as you are not using memcached).
The linux futex bug (have to wait for someone to help look up whether
your kernel version is affected).

Could you paste more of your log file?  If you want to hide your site just
replace your domain name in the file first.
-Josh
On Thu, Jun 11, 2015 at 7:45 PM, giggioman00<EMAIL_ADDRESS>wrote:

Nope, I'm not out of space... My VPS have 23.04 GB of total space but only
6 GB are used.
Spache childrn runs as: user
and permissions of /var/cache/mod_pagespeed are user:user
Usually I don't get this error. It appears only when appears the Waiting
for completion of URL problem
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-111308028
.

This is what I get if I type df -i:
Filesystem       Inodes  IUsed    IFree IUse% Mounted on
/dev/sda1      24165376<PHONE_NUMBER>5346    1% /
devtmpfs         254703    318   254385    1% /dev
tmpfs            256195      1   256194    1% /dev/shm
tmpfs            256195    339   255856    1% /run
tmpfs            256195     13   256182    1% /sys/fs/cgroup
But I need to say that today my site didn't gone offline.
Next time I'll try with lsof but it's hard... Usually I get notification from pingdom when my VPS goes offline, but usually in that time I'm not online so I cannot check. And when I'm online the problem is gone (Just I said, it appears only for 2-5 minutes... )
Now I send you the log of yesterday: http://pastebin.com/c0sBSXLV
Then the VPS went online again. Domain and VPS IP are hide.

Hello,
For one javascript that was giving "Waiting for ..." messages, with Apache2 debug log on,  I have had a mod_pagespeed error message that says that there is a problem with it. I m looking after it to publish it. I disallow mod_pagespeed to rewrite it - not a big concern.
For images, it seems that images that are giving "Waiting for ..." messages, are always the same one, there is clearly something that is reduntant. And most of them have disappeared from top positions in Google image.
I have change nothing to the use : IPRO, LoadFromFile ...BandWidthSave
I have give more ressources to the domain (which has been moved alone) : 8Gb RAM, 6 cores, 3GB memcached, 100Mb bandwith up and down, for about 100000 apache reqs/day and the messages still occures.
I let go for few days run (without debug log) and see.
Greatings,
Eric

Hello,
This command should help some to count and see how many and which files are concerned :

awk -F'[[]]+' '$4 == "warn"{print $7}' /var/log/apache2/error.log | sort | uniq -c | sort -nr | grep " 5 sec" | more

See here if explanations needed : http://sudarmuthu.com/blog/how-to-print-unique-errorswith-count-from-apache-error-logs/
Greatings,
Eric

We've built a test release with @jeffkaufman's fixes to the ApacheFetch.
If you've been experiencing this bug, please give it a try and let us know if it fixes the issue for you.
The packages can be found here https://github.com/pagespeed/mod_pagespeed/releases/tag/
Thanks in advance for your feedback!

We've built a test release with @jeffkaufman's fixes to the ApacheFetch.
If you've been experiencing this bug, please give it a try and let us know if it fixes the issue for you.
The packages can be found here https://github.com/pagespeed/mod_pagespeed/releases/tag/<IP_ADDRESS>
Thanks in advance for your feedback!

Is anyone still having this bug?
We're preparing a release with a mitigation for the bug, but because we haven't been able to reproduce it here it would be really very helpful if someone could install the packages @crowell built [1] and see if this issue recurs.
[1] https://github.com/pagespeed/mod_pagespeed/releases/tag/<IP_ADDRESS>

Closing this issue, because the ApacheFetch mitigations should be sufficient for the cases we've seen reported.  If this is still happening to you after <IP_ADDRESS> please reopen.

Update to my comment above:

Having your cache on a memcached should not trigger this message, even if memcached is slow.  PageSpeed has good timeouts around memcached and this code is stable.
Having your filecache or LoadFromFile target on a slow filesystem can trigger this bug, if the filesystem takes more than 5s to respond.  If fread hangs, perhaps because of an unreachable nfs server, then in mod_pagespeed < <IP_ADDRESS> the relevant apache and pagespeed optimized threads will be stuck, while in mod_pagespeed >= <IP_ADDRESS> the apache thread will be released after 2min and only the pagespeed optimizer thread will be stuck.

To reproduce this:

Set up load from file for some file named style.css.
Patch mod_pagespeed:

--- a/kernel/base/stdio_file_system.cc
+++ b/kernel/base/stdio_file_system.cc
@@ -107,6 +107,16 @@ class StdioInputFile : public FileSystem::InputFile {
}
virtual int Read(char* buf, int size, MessageHandler* message_handler) {

StringPiece spfname(file_helper_.filename_);
if (spfname.ends_with("style.css")) {

 while (true) {

   LOG(WARNING) << "Read("

                << file_helper_.filename_ << ") is sleeping";

   sleep(1);

 }

} else {

 LOG(WARNING) << "Read(" << file_helper_.filename_ << ") allowed";

}
int ret = fread(buf, 1, size, file_helper_.file_);
file_helper_.CountNewlines(buf, ret);
if ((ret == 0) && (ferror(file_helper_.file_) != 0)) {

* fetch `style.css` from your patched server
* observe "waiting for completion of url" messages

Like most software, PageSpeed assumes that file reads are effectively non-blocking, and doesn't perform well if they take a significant amount of time.

Does this imply that we should be handling those filesystem operations off the main thread?  That'd be annoying for the common case of cache hit, but doable.

@jmaessen Or maybe stdio_file_system should just switch to something that times out if loads take too long?
But I'm not sure it's worth it.  This bug here is basically two issues:
a) Occasional messages about "waiting for completion of url", with only minor performance degradation
b) Incessant messages about "waiting for completion of url", with major performance degradation
Reads taking more than 5s but still completing will trigger (a).  In this case the message is effectively a reminder that you have high tail latencies for file reads and that this is hurting PageSpeed's performance. The fix here seems like operators making sure PageSpeed has fast access to anything it thinks is a filesystem.
The second case, (b), is probably a race condition in the linux futex code that's been patched for a while now and shouldn't be affecting people, though it would also be caused if a branch of our code fails to call a callback.

Well, to time out an fread I think you have to step outside stdio and use raw file descriptors.  Which might or might not make sense for places where we're doing full-file reads.  Arguably we should just have sendfile support in those situations, though, even if it solves a slightly different but related problem.

[So basically I agree, sorry, meant to say that.]

@jmaessen "arguably we should just have sendfile support in those situations"
Unless we're reading the file in so we can optimize it.

I am going to add some diags to StdioFileSystem to track and log slow operations.

we have a second "testing" build with a fix for a race condition in ApacheFetch  as well as logging for slow file io operations and some small tweaks for BoringSSL compatibility.
(see https://github.com/pagespeed/mod_pagespeed/wiki/Release-<IP_ADDRESS> for changes)
If anyone who has experienced the issue in this bug can give it a try, please let us know if
1: this solves the problem
2: you notice any log messages about slow file operations.
We hope to have a proper release out including these fixes soon after hearing back from testers!
https://github.com/pagespeed/mod_pagespeed/releases/tag/<IP_ADDRESS>
deb/rpm are available here, as well as the .tar.bz2 for building from source

reopening after getting some logs from people experiencing this issue.

@crowell has succeeded at reproducing this here with a testing site set up with the configuration and resources of one of the people reporting the issue.  Debugging should be faster now.

symbolized backtrace from my machine https://gist.github.com/anonymous/417c35a0f7cdfe835f58

some interesting (possibly) logs with AprMemCache errors.
https://gist.github.com/crowell/a6904d089c01c4f55d9d

second round of backtraces https://gist.github.com/7ea4af43e4f1484c4100

Thank you @crowell and @jeffkaufman for your perseverance.
Now I'm writing from the company account, but I've already wrote you as @capn3m0 and I'm sorry that I've couldn't done the tests that you have requested: those servers are still in production so, once that the problem has been solved I didn't feel safe to try the test another time threatening to make it unstable.
I am confident that the problem will be solved as soon as possible, meanwhile I hope you have a good job and I would like to say thank you from the WpSEO Staff and our Clients.

I just went through the four recent backtraces we have and classifies the states of the threads:
1 32  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
1 31  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
1 30  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
1 29  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
1 28  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
1 27  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
1 26  ap_process_request > ap_core_output_filter > poll
1 25  ap_queue_pop > pthread_cond_wait
1 24  ap_process_request > ap_core_output_filter > poll
1 23  ap_queue_pop > pthread_cond_wait
1 22  ap_queue_pop > pthread_cond_wait
1 21  ap_process_request > ap_core_output_filter > poll
1 20  ap_process_request > HandleAsPagespeedResource
                         > ap_core_output_filter > poll
1 19  ap_process_request > HandleAsPagespeedResource > BoundedWaitFor
                         > pthread_cond_timedwait
1 18  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
1 17  ap_queue_pop > pthread_cond_wait
1 16  ap_queue_pop > pthread_cond_wait
1 15  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
1 14  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
1 13  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
1 12  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
1 11  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
1 10  ap_queue_pop > pthread_cond_wait
1 09  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
1 08  ap_process_request > HandleAsPagespeedResource > BoundedWaitFor
                         > pthread_cond_timedwait
1 07  ap_unixd_accept > accept4
1 06  WorkThread::Run > QueuedWorkerPool::Run > ApacheWriter::Write > deflate
1 05  WorkThread::Run > pthread_cond_wait
1 04  WorkThread::Run > pthread_cond_wait
1 03  WorkThread::Run > pthread_cond_wait
1 02  SerfThreadFn > TransferFetchesAndCheckDone > pthread_cond_timedwait
1 01  main > ap_run_mpm > ap_mpm_podx_check > read

2 32  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 31  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 30  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 29  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 28  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 27  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 26  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 25  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 24  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 23  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 22  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 21  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 20  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 19  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 18  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 17  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 16  ap_process_request > ap_core_output_filter > poll
2 15  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 14  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 13  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 12  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 11  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 10  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 09  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
2 08  ap_process_request > RewriteDriver::FinishParse > pthread_cond_timedwait
2 07  ap_queue_info_wait_for_idler > pthread_cond_wait
2 06  WorkThread::Run > QueuedWorkerPool::Run > ApacheWriter::Write > poll
2 05  WorkThread::Run > pthread_cond_wait
2 04  WorkThread::Run > pthread_cond_wait
2 03  WorkThread::Run > pthread_cond_wait
2 02  SerfThreadFn > TransferFetchesAndCheckDone > pthread_cond_timedwait
2 01  main > ap_run_mpm > ap_mpm_podx_check > read

3 26  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 25  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 24  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 23  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 22  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 21  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 20  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 19  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 18  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 17  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 16  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 15  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 14  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 13  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 12  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
3 11  WorkThread::Run > pthread_cond_wait
3 10  WorkThread::Run > AprMemCache::MultiGet > epoll_wait
3 09  WorkThread::Run > pthread_cond_wait
3 08  WorkThread::Run > pthread_cond_wait
3 07  WorkThread::Run > pthread_cond_wait
3 06  WorkThread::Run > pthread_cond_wait
3 05  SerfThreadFn > TransferFetchesAndCheckDone > pthread_cond_timedwait
3 04  WorkThread::Run > pthread_cond_wait
3 03  WorkThread::Run > pthread_cond_wait
3 02  WorkThread::Run > pthread_cond_wait
3 01  main > ap_run_mpm > apr_thread_join > pthread_join

4 35  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 34  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 33  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 32  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 31  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 30  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 29  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 28  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 27  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 26  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 25  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 24  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 23  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 22  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 21  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 20  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 19  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 18  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 17  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 16  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 15  ap_queue_pop > pthread_cond_wait
4 14  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 13  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 12  ap_process_request > ApacheFetch::Wait > pthread_cond_timedwait
4 11  ap_process_request > RewriteDriver::Flush > pthread_cond_timedwait
4 10  unixd_accept > accept4
4 09  WorkThread::Run > pthread_cond_wait
4 08  WorkThread::Run > AprMemCache::MultiGet > epoll_wait
4 07  WorkThread::Run > pthread_cond_wait
4 06  SerfThreadFn > TransferFetchesAndCheckDone > pthread_cond_timedwait
4 05  WorkThread::Run > pthread_cond_wait
4 04  WorkThread::Run > pthread_cond_wait
4 03  WorkThread::Run > pthread_cond_wait
4 02  WorkThread::Run > pthread_cond_wait
4 01  main > ap_run_mpm > ap_mpm_pod_check > read

We need to learn which thread or threads are spinning and burning 100% cpu, since the backtraces don't look like they should be spinning.
@crowell When you next manage to reproduce this, could you run:
$ ps -p [PID] -w -w -L -o %cpu,lwp,pid,user,args

On the apache process taking 100% CPU?  Then in gdb we can see which thread has that LWP id.
For example, on my system (not having the problem) I currently see:
$ ps -p 3753 -w -w -L -o %cpu,lwp,pid,user,args
%CPU   LWP   PID USER     COMMAND
 0.0  3753  3753 jefftk   /usr/local/apache2/bin/httpd -k start
 0.0  3754  3753 jefftk   /usr/local/apache2/bin/httpd -k start
 0.0  3755  3753 jefftk   /usr/local/apache2/bin/httpd -k start
 0.0  3756  3753 jefftk   /usr/local/apache2/bin/httpd -k start

And when I look in gdb:
> thread apply all bt
...
Thread 3 (Thread 0x2b8e8bf27700 (LWP 3755)):
...

The way PthreadCondvar::TimedWait in pagespeed/kernel/thread/pthread_condvar.cc is not checking the return code on pthread_cond_timedwait doesn't look right.  Now, pthread_cond_timedwait should only return a few errors but if we gave one invalid input it would spin forever.

The only checking that seems appropriate for those would be a CHECK ----
ETIMEOUT is the only one that can happen barring major bugs in our code,
and ignoring ETIMEOUT is the right thing to do.
On Thu, Aug 20, 2015 at 7:50 AM, Jeff Kaufman<EMAIL_ADDRESS>wrote:

The way PthreadCondvar::TimedWait in
pagespeed/kernel/thread/pthread_condvar.cc is not checking the return
code on pthread_cond_timedwait doesn't look right. Now,
pthread_cond_timedwait should only return a few errors
http://pubs.opengroup.org/onlinepubs/009695399/functions/pthread_cond_timedwait.html
but if we gave one invalid input it would spin forever.
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-132984670
.

@morlovich agreed

backtrace with on a debug build, along with thread process stats.
https://gist.github.com/e5f323af7e879c226e91

@crowell That's very strange; doesn't look like 100% cpu at all?  Only 25951 and 25901 are at all busy, and they're doing actual work, not waiting around like in our other backtraces.

@crowell I count 11 of 36 threads as doing real cpu-involving work as opposed to waiting, while on the other backtraces it was at most 1.

@jeffkaufman when i has the problem only 1 or 2 httpd.worker stuck with high cpu but all the rest httpd process working normally

There are some stack-frames that look concerning:
Thread 8 (Thread 0x7f7e85feb700 (LWP 25875)):
#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at
../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1 0x00007f7e9bb24e47 in net_instaweb::PthreadCondvar::TimedWait
(this=0x7f7e7431be38, timeout_ms=0) at
pagespeed/kernel/thread/pthread_condvar.cc:66
#2 0x00007f7e9b906bac in
net_instaweb::CheckingThreadSystem::CheckingCondvar::TimedWait
(this=0x7f7e744faf68, timeout_ms=5000) at
pagespeed/kernel/base/checking_thread_system.cc:55#3 0x00007f7e9b62e9bc in
net_instaweb::ApacheFetch::Wait (this=0x7f7e741220a8,
rewrite_driver=0x7f7e80135298) at pagespeed/apache/apache_fetch.cc:199
On Thu, Aug 20, 2015 at 2:40 PM, WpSEO.it Hosting WordPress e Consulenza
SEO<EMAIL_ADDRESS>wrote:

@jeffkaufman https://github.com/jeffkaufman when i has the problem only
1 or 2 httpd.worker stuck with high cpu but all the rest httpd process
working normally
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-133112237
.

@jmarantz yeah, this is also the case in other threads/processes
(gdb) where
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f7e9bb24e47 in net_instaweb::PthreadCondvar::TimedWait (this=0x7f7e9033d178, timeout_ms=0)
    at pagespeed/kernel/thread/pthread_condvar.cc:66
#2  0x00007f7e9b906bac in net_instaweb::CheckingThreadSystem::CheckingCondvar::TimedWait (this=0x7f7e902136c8,
    timeout_ms=5000) at pagespeed/kernel/base/checking_thread_system.cc:55

the code for the function in frame 2
  virtual void TimedWait(int64 timeout_ms) {
    mutex_->DropLockControl();
    condvar_->TimedWait(timeout_ms);
    mutex_->TakeLockControl();
  }

so there really should be no reason for timeout_ms being reset to 0...

Never mind; that was a red herring; PthreadCondvar::TimedWait overwrites
that formal and it winds up holding the number of miliseconds.  But the
data is not lost.
int64 timeout_sec_incr = timeout_ms / Timer::kSecondMs;
timeout_ms %= Timer::kSecondMs;
// Figure out current time, compute absolute time for timeout
// Carrying ns to s as appropriate.  As morlovich notes, we
// get really close to overflowing a 32-bit tv_nsec here,
// so this code should be modified with caution.
if (gettimeofday(&current_time, NULL) != 0) {
LOG(FATAL) << "Could not determine time of day";
}
timeout.tv_nsec = current_time.tv_usec * 1000 + timeout_ms * kMsNs;
timeout_sec_incr += timeout.tv_nsec / Timer::kSecondNs;
timeout.tv_nsec %= Timer::kSecondNs;
timeout.tv_sec = current_time.tv_sec +
static_cast<time_t>(timeout_sec_incr);
// Finally we actually get to wait.
pthread_cond_timedwait(&condvar_, &mutex_->mutex_, &timeout);
-Josh
On Thu, Aug 20, 2015 at 2:58 PM, Joshua Marantz<EMAIL_ADDRESS>wrote:

There are some stack-frames that look concerning:
Thread 8 (Thread 0x7f7e85feb700 (LWP 25875)):
#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at
../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1 0x00007f7e9bb24e47 in net_instaweb::PthreadCondvar::TimedWait
(this=0x7f7e7431be38, timeout_ms=0) at
pagespeed/kernel/thread/pthread_condvar.cc:66
#2 0x00007f7e9b906bac in
net_instaweb::CheckingThreadSystem::CheckingCondvar::TimedWait
(this=0x7f7e744faf68, timeout_ms=5000) at
pagespeed/kernel/base/checking_thread_system.cc:55#3 0x00007f7e9b62e9bc in
net_instaweb::ApacheFetch::Wait (this=0x7f7e741220a8,
rewrite_driver=0x7f7e80135298) at pagespeed/apache/apache_fetch.cc:199
On Thu, Aug 20, 2015 at 2:40 PM, WpSEO.it Hosting WordPress e Consulenza
SEO<EMAIL_ADDRESS>wrote:

@jeffkaufman https://github.com/jeffkaufman when i has the problem
only 1 or 2 httpd.worker stuck with high cpu but all the rest httpd process
working normally
—
Reply to this email directly or view it on GitHub
https://github.com/pagespeed/mod_pagespeed/issues/1048#issuecomment-133112237
.

(gdb) p timeout_sec_incr
$6 = 5
(gdb) p timeout
$7 = {tv_sec =<PHONE_NUMBER>, tv_nsec = 332683000}

yeah seems to be a valid 5 second wait.

https://gist.github.com/903957a54f2cebcbe1b8
3 stack traces before it got out of the "Waiting for completion" state  looking now.

some stack traces ~30 seconds apart, with 1 rewrite thread in config.
https://gist.github.com/63d0b4e6c4c406d2b2d3
they're all identical.  after stopping the load on the server, the issue cleared up.

https://github.com/pagespeed/mod_pagespeed/releases/tag/<IP_ADDRESS> should fix the issue.
anyone who has been affected by this, please give this pre-release a try and report back!

installed.
I will give you a feedback in the next days.
Thanks for all

While we're confident now that the "Waiting for Completion" state has been fixed, there seems to be a second, related, issue of hangs within apr_memcache2_multgetp
It may be possible for apr_pollset_poll to return a value that isn't APR_SUCCESS due to a failure that isn't a timeout.
It may also be possible for get_server_line to be called with conn->bb as empty, causing infinite reads of size zero.
We're working on testing these, and will have a test binary soon for interested users.

Installed <IP_ADDRESS> on production this morning after having run it succesfully in test for 2 weeks. Tonight
unfortunately waiting for completion starts occurring again:
[Tue Sep 22 22:05:35 2015] [warn] [mod_pagespeed <IP_ADDRESS>-7388 @13009] Waiting for completion of URL http://m.xxxxx.nl/m20/?gclid=xxx for 110.002 sec.
[Tue Sep 22 22:05:35 2015] [warn] [mod_pagespeed <IP_ADDRESS>-7388 @16737] Waiting for completion of URL http://m.xxxxx.com/wcsstore/dojo18/dijit/layout/TabContainer.js for 100.002 sec.
[Tue Sep 22 22:05:35 2015] [warn] [mod_pagespeed <IP_ADDRESS>-7388 @1573] Waiting for completion of URL http://m.xxxx.nl/m20/?gclid=xxxx 75.002 sec.
[Tue Sep 22 22:05:35 2015] [warn] [mod_pagespeed <IP_ADDRESS>-7388 @13522] Waiting for completion of URL http://m.xxxx.com/wcsstore/dojo18/dijit/layout/_TabContainerBase.js for 70.001 sec.
[Tue Sep 22 22:05:35 2015] [warn] [mod_pagespeed <IP_ADDRESS>-7388 @17553] Waiting for completion of URL http://m.xxxx.com/wcsstore/dojo18/dijit/form/DropDownButton.js for 80.002 sec.

25.000+ times in 15 minutes and then all seems to be fine again. Only happened on 1 out of 3 webservers, but seems to be same behavior as before <IP_ADDRESS>

@sv72: Did the CPU usage go to 100% when this happened?

Actually no, CPU was not higher than normal (30-35%), but memory usage did go to 95% (normally around 50%)

Hello,
I have pushed mod_pagespeed <IP_ADDRESS>-7423 to production server (only one domain) and re-enabled rewrite of images in fullsize to test it.
That seem to be ok.
I have those error in apache error.log, a few ones, less than 1 % of rewrited images :
configure SlowFileLatencyUs to change threshold.
Is it a new mod_pagespeed parameter or should we use an existing one ?
My conf :
Version: 14: on
Filters
cw	Collapse Whitespace
jc	Combine Javascript
gp	Convert Gif to Png
jp	Convert Jpeg to Progressive
jw	Convert Jpeg To Webp
pj	Convert Png to Jpeg
dj	Defer Javascript
hw	Flushes html
io	In-place optimize for browser
idp	Insert DNS Prefetch
js	Jpeg Subsampling
pr	Prioritize Critical Css
rj	Recompress Jpeg
rp	Recompress Png
rw	Recompress Webp
rc	Remove Comments
cf	Rewrite Css
jm	Rewrite External Javascript
jj	Rewrite Inline Javascript
cp	Strip Image Color Profiles
md	Strip Image Meta Data
Options
CssInlineMaxBytes (ci)            10240
EnableCachePurge (euci)           True
EnableRewriting (e)               1
FileCacheCleanIntervalMs (afcci)  3600000
FileCachePath (afcp)              /var/cache/mod_pagespeed/
FileCacheSizeKb (afc)             4096000
ImplicitCacheTtlMs (ict)<PHONE_NUMBER>0
LoadFromFileCacheTtlMs (lfct)<PHONE_NUMBER>0
LogDir (ald)                      /var/log/pagespeed
LRUCacheByteLimit (alcb)          16384
LRUCacheKbPerProcess (alcp)       1024
MemcachedServers (ams)            localhost:11211
RequestOptionOverride (roo)
RewriteDeadlinePerFlushMs (rdm)   20
RewriteLevel (l)                  Optimize For Bandwidth
SslCertDirectory (assld)          /etc/ssl/certs
StatisticsLogging (asle)          True
SupportNoScriptEnabled (snse)     False
UrlSigningKey (usk)
Domain Lawyer
http://www.opalesurfcasting.net/ Auth

@eldk that is just a diagnostic message, letting you know that the time to read a file from disk passed an arbitrary amount of time that we determined to be "slow", it doesn't impact performance, just the message is logged, nothing is cancelled or unscheduled. If you want to silence this, you can configure the SlowFileLatencyUs to a higher number.

Thanks.