Photo Organizer

  • Status Closed
  • Percent Complete
    100%
  • Task Type Bug Report
  • Category Backend / Core
  • Assigned To No-one
  • Operating System All
  • Severity Medium
  • Priority Very Low
  • Reported Version 2.34-rc3
  • Due in Version Undecided
  • Due Date Undecided
  • Votes
  • Private
Attached to Project: Photo Organizer
Opened by doc - 2007-08-16
Last edited by pizza - 2007-08-25

FS#271 - PHP Timeout on bulk updates with watermarking

Huh... I'd like to remake some 316 watermarks in a folder, but unfortunately, the process stops after some 30+ pictures.

PHP Fatal error:
Maximum execution time of 30 seconds exceeded in
/var/www/po.bugslayer.de/html/include/import.php on line 54, referer:
http://po.bugslayer.de/my.tools.php

The dreaded execution time again. Anything to to against it?
The machine is not *that* fast, and a large folder might take it's time...

The actual Revision is r1588 :)

Closed by  pizza
2007-08-25 14:11
Reason for closing:  Fixed
Additional comments about closing:  I went ahead and eliminated the runtime limit on the upload and bulk update pages... I can't see a better solution for now.
Admin
pizza commented on 2007-08-16 11:52

Did you have any problems doing a bulk upload of more than, say, 30 files at once? The only times I've hit the execution time limit is when there was a bug in the code causing some sort of infinite loop, as the execution time limit only applies to PHP native code, not the external apps like RAW decoders, ImageMagick, etc..

Offhand, I can't think of anything that would cause this, beyond a fairly slow host processor.

I routinely upload several hundred RAW images at a time (with an execution limit of 180) on my dual P3 server. I rarely use watermarking, as the long list of problems with it can attest. :)

Was there anything of use in the the httpd logs?

doc commented on 2007-08-16 12:08

Yes and no. I uploaded hundreds of photos in a single, really lengthy, session, but that was 2.33d on the previous host.
Since then I just edit the results and hunted bugs with You :-)
It is quite possible, that there is a loop resulting from a single foto. Hmmm. I'll check that. Stay tuned!

doc commented on 2007-08-16 12:23

Ok, I have nothing to upload right now. But the picture, where the process broke, seems to be fine. I can watermark the rest.
The 30 seconds seem to apply to the whole bulk update process (or the loop construct within).

Please find the log parts enclosed. The warnings are sort of ubiquitous...

   log (3.3 KiB)
Admin
pizza commented on 2007-08-16 12:23

One possible culprit -- photos with multiple versions, and the possiblility that you may be watermarking your watermark image..

doc commented on 2007-08-16 12:26

Nope, I am really sorry :-(

Each photo can be re-watermarked independently or in groups, but not all of them, or too many of them.

Admin
pizza commented on 2007-08-16 13:39

You seem to be using -rc3 rather than svn head, but I don't expect any change in behaivor (except for fewer warnings in the logs)

How much walltime elapses before the timeout hits?

Are any of these RAW images?

Admin
pizza commented on 2007-08-16 13:41

And can you cut'n'paste the on-screen output as well?

doc commented on 2007-08-16 14:05

You are right, the po is svn-r1588 from the "stable" branch.
"devel" is just too hot for my site.
Plus I am aiming to help for a good stable release :-)

The output just stops (Browser says "Done.") after "Generating thumbnail image ... done. (170 pixels)":

# Regenerating thumbnail and preview images for photo # 3265-3257: .

* Generating preview image ... done. (700 pixels)
* Watermarking image ... done.
* Transferring metadata ... done.
* Generating thumbnail image ... done. (170 pixels)

The complete run is in the attached log.
I was wrong with the wall time. Wall time was 2 minutes 35 seconds.
The images are plain JPEG from a Fujitsu FinePix Zoom 2400.

Hope it helps, anyway.

   log (5.5 KiB)
doc commented on 2007-08-17 10:48

Just to add a new facet to the mosaic: I just bulk updated 30 pics (jpeg) and after 19 pics, the session simply hung ("Transferring data..."). I had to shut down the apache to get it "Done.". No message in the error log at all (besides the omnipresent one)

PHP Warning: Invalid argument supplied for foreach() in /var/www/po.bugslayer.de/html/bulk.update.php on line 62, referer: http://po.XXXX/my.tools.php?selector=1&type=folder&selection=96

Oh, yes, the next try gave the normal 30 seconds timeout.

Admin
pizza commented on 2007-08-17 13:56

that PHP warning was fixed a little while back, in r1568 I believe.

I haven't been able to recreate it here yet, but I'll try that later today.

doc commented on 2007-08-24 09:01

Hmmm I updated to 1637, but the behaviour is the same. After about 20 pictures of watermarking, the show is over.

Any idea?

Admin
pizza commented on 2007-08-24 15:09

Out of curiousity, is it always the same image that it dies on?

I simply haven't been able to recreate this; granted I only have 23 images on this particular server, but even when I set the execution time limit down to 5s (on a p3-1000) they all finish successfully.. and several of them are RAW.

I'm uploading another 30 now.

Admin
pizza commented on 2007-08-24 15:28

I just did a bulk update of 75 images successfully, still with the execution limit of 5s.

doc commented on 2007-08-24 15:48

I understand. No worries. Since it seems to be a really strace kind of lockup anywhere in the tool chain, I'll try to instrument the code and have a look.
It should not take too much of PHP knowledge to do so. We'll see.
I'll report on the issue in this ticket :-)

doc commented on 2007-08-24 18:29

Ok, I can tell this much: The process dies in import.php-"dirsize()", at various positions (at start of the outer loop, or another time).

It is hard to see, what is going on, since it is a loop with 224 or 482 iterations each. But when it is basically the same loop for each picture (the were uploaded together and are in the same album and folder) I cannot see the point, why it is cancelled sometimes.

Admin
pizza commented on 2007-08-24 18:47

You didn't answer my earlier question -- does it fail on the same image each time, or is it always the (for example) 20th image processed? I have a pretty good idea about what's going on though.

First, how many files are there in your PO repository? How about the current repository volume?

Okay.. get_current_volume() calls dirsize().. which is used to figure out if it's time to move to a new volume. It does this for each preview/thumb image you're resizing.. which is a lot!

Now that file sizes etc are kept in the database, there's no reason why we should be going through all of this manual re-calculation... time to do a little rewriting!

doc commented on 2007-08-24 19:02

Sorry, I did not answer, because I am not *quite* sure. Some days ago, different runs with the same selection broke on different images (off by 1 or 2).

For the numbers:

v0005 Yes 352.84 / 640 MB (55%) 1182 3 July 3, 2007 Edit
v0004 640.03 / 640 MB (100%) 1185 3 July 3, 2007 Edit
v0003 635.31 / 640 MB (99%) 2274 3 July 3, 2007 Edit
v0002 607.36 / 640 MB (94%) 3469 3 June 13, 2007 Edit
v0001 518.37 / 640 MB (80%) 2606 3 June 12, 2007 Edit
v0000 428.37 / 640 MB (66%) 2544 3 June 11, 2007 Edit

And I instrumented the code in an obvious way, printing out some time() and parameters:

ME: begin dirsize... [/var/share/po-data/v0005/00002]:1187981670
ME: end dirsize (Array, count=482)...
ME: end dirsize (Array, count=5)...
# Regenerating thumbnail and preview images for photo # 71-69: .

* Generating preview image ... done. (700 pixels)
* Watermarking image ... done.
* Transferring metadata ... done.
* ME: start thumbing:1187981683Generating thumbnail image ... done. (170 pixels)
ME: end thumbing (1):1187981685
ME: got size:1187981685
ME: got size:1187981685
ME: begin dirsize... [/var/share/po-data/v0005]:1187981686
ME: begin dirsize... [/var/share/po-data/v0005/00000]:1187981686

In the last run, it was number #69 that was last. So, it is *not* exactly the same picture each time :-(

The timestamps don't look bad. Two seconds are fairly ok. No reason to kill the code.

How is the PHP timeout set and reset? I have absolutely no idea about that PHP magic.

Admin
pizza commented on 2007-08-24 19:08

Try svn r1640. I rewrote dirsize() to use the database instead of walking the filesystem. I thought I'd already done this a while ago, but I guess I was mistaken..

I'm guessing that PHP is spending all of its CPU time walking the directories... which in your case I'm guessing are relatively large.

Admin
pizza commented on 2007-08-24 19:26

Thanks for the extra details; the fact that it's breaking on different images shows that it's not a corrupted image file.

However, thinking about this.. it would affect bulk uploads as well as updates, so the rewrites in r1640 probably won't solve this problem.

print ini_get('max_execution_time');

will give you your current timelimit. It's set in /etc/php.ini and AFAIK can't be overridden by a script.

Admin
pizza commented on 2007-08-24 19:32

Apparently the set_time_limit() call can override the max execution time.

set_time_limit(600) will let it run for ten minutes, for example.. But I still wonder what the root cause of this timeout is; *something* is eating up your CPU resources...

doc commented on 2007-08-24 20:17

Ah, this is it!

I read something about time_limit() and is does NOT take OS activity, waiting times etc. into account. So the 30 seconds are NOT user time.

This makes perfect sense, since my machine is *really* not fast, and re-thumbing costs a lot of real CPU time, even within the PHP code itself.
So, when the whole loop has to be completed in 30 seconds, there is no way with this machine.

I added an explicit "set_time_limit(30)" to the code path calling the thumbnail image generation (yes, this is *not* the best place) giving each photo 30 seconds (which is a bit much CPU time) and now it runs through.

Anything constant for the whole re-generation loop might break anywhere, where a large job has to be done. Whatever "large" may be :-)

Admin
pizza commented on 2007-08-24 20:45

The thing is, I'd expect you to have problems with uploads as well, as that's more CPU intensive than re-thumbing. But you said you had no problem uploading large batches at once on the same machine.

I do not want to make this value unlimited -- set_time_limit(0); -- but I don't know if there's a better solution, given that we have no real idea what "large" is.

doc commented on 2007-08-24 21:02

AFAIK I made no new uploads with this version. My last $LARGE Uploads were with 2.33d, or so. With 2.34 I was stuck with editing, sorting, tagging, debugging.

I agree, that "unlimited" is no solution. I suggest a fairly short CPU time slice FOR EACH photo. Somewhat like this (that works perfectly for me):

/* Thumbnail */
if ($result) {
set_time_limit(10); # ME!!!
$result = import_generate_thumbnail($original_name, $image_repository_pat[.......]
}

10 seconds is a long time for an individual photo, and a short time enough to escape a dead lock.

Loading...

Available keyboard shortcuts

Tasklist

Task Details

Task Editing