Image (Resize, Crop, ...) doesn't use previous generated files

@robert:
Are you sure, that the PHP process runs 24 h a day?

On some cheap installations, the PHP process dies after some time of not running. The PHP process then needs to start for the “first” webpage, what needs some time. The next webpage is very much faster…

What @anon77445132 wrote is correct. Starting up a PHP worker takes a lot of time (a few seconds), so if there is none because there haven’t been requests in a while, it’s normal for the first page load to be slower. And because that startup time is spent before Kirby is even loaded, we can’t do anything against that.

What you could try to verify if this worker timeout is the issue:

  1. Load a page with many thumbs, note down the response time.
  2. Load the page again, note down the response time.
  3. Wait for a “longer period”.
  4. Load a page that doesn’t have any thumbs and note down the response time.

If the page without thumbs takes long to load as well, it can’t be related to thumbs.

1 Like

@lukasbestle @anon77445132 No, it’s not the starting up of a PHP worker:
The concrete website is hosted at a provider and starts with a login-page - without any image. This login-page comes as fast as it should. The website is a gallery of a approx. hundred of images. This gallery is paginated, so that on every page a dozen of images are shown. The long loads are on every new (paginated) page. When a page is reloaded the loads are very quick.

To mention it explicit: The load times are measured on server side.

1 Like

@robert:
Does the website or your hoster use any cache or CDN?
Does your browser use any add-in that shows something like a cache?
Have you changed your /site/config/config.php to use the Kirby cache or another cache or CDN?

Answer to all questions: No

The only cache that’s enabled is the opcache-module of PHP.

I would look at the …

May be, stop the opcache-module for a test and look for your error, is this error gone?

Thanks for the details. I agree that it can’t be the worker processes then. I’d also rule out the OpCache as that only caches the code files, not any type of generated content.

But the issue is still strange. I don’t know where to start debugging as I can’t reproduce it. :slightly_frowning_face:

@anon77445132 Deactivating the opcache-module results only in slower overall performance of execution of kirby.

@lukasbestle As mentioned in my post from 2017-01-30 there seems to be a problem with the execution of call_user_func_array($function, $arguments) in toolkit/helpers.php. The calls results in slow “first time execution” for the image-objects. Maybe this is an PHP-internal effect?!

Theoretically, the execution of call_user_func_array() was optimized in PHP7, but in this case it is not faster.

As I have not enough PHP-knowledge, I’m not able to further investigate the specific calls, which are executed during getting/preparing an image.

1 Like

I can’t be call_user_func_array(), especially not because we use this function (with Kirby’s call() helper) a lot, not only for thumbs.

But of course call_user_func_array() calls a function and that function might/will be the bottleneck (or some other function that is called by that function). However we don’t know where to start debugging if we can’t reproduce the issue.

@lukasbestle Is there a way to produce a log (including timing) with “all” inner-calls for call_user_func_array()? I’m not that familiar with PHP, so I need assistance to do that. After that I can give you the resulting log-file.

That’s a good idea. You can use Xdebug’s Profiler for this.

@lukasbestle It’s curious. When Xdebug is enabled, the logged timings says that the site runs faster with Xdebug enabled in comparison to when Xdebug is disabled. That can’t be right. And the fact is, that the site doesn’t runs faster, only Xdebug tells it runs fast. ???

E.g. Xdebug says that in worst case the site needs 670 ms to load (best case 120 ms - both would be fine). But in real the site needs approx. 4500 ms (timings measured by FireFox). The GET page itself needs this time (page-size: 2,4 KiB). All other elements like images and scripts are taken from FireFox’s cache (0 ms).

Where did you get the Xdebug timings from?

PHP-Version: 5.6.30
htaccess: php_value xdebug.profiler_enable 1
Xdebug-Version: 2.5.0

  • xdebug.profiler_output_name: cachegrind.out.%p
  • xdebug.max_nesting_level: 256

Log-Analyzers (same file, {main}):

  • WinCacheGrind 1.1.0.16 (675 ms)
  • QCachegrind 0.7.4 (101 ms)

Can you see in the profiler log where most of the execution time is spent?

I switched back to PHP 7.1 and deactivated Fast-CGI. Here are the results:

WinCacheGrind:

QCachegrind:

The results tell us that site/snippets/gallery.php is the file that generates the largest part of the delay in this request. But they don’t tell us which function that is called by the snippet is the issue (the thumb stuff itself is very fast with 34ms). Could you please post the gallery snippet?

<!-- Snippet:Gallery -->
<?php if(!defined('KIRBY')) exit;

	if ($items->count()>0) {
		echo '<div class="row">';
		
		$index = -1;
		foreach($items as $item) {
			$index++;
			
			if (($index % 5) < 2) $class = 'col-xs-12 col-sm-6 col-md-6';
			else $class = 'col-xs-12 col-sm-6 col-md-4';
			
			$width = 750;
			$height = round($width * 9/16, -1);
			
			$time_start = microtime(true);
			
			if ($item->image())
				$newimage = $item->image()->crop($width, $height, 15);
			else $newimage = null;

			$time_end = microtime(true);
			$time = $time_end - $time_start;

			if ($newimage) {
				echo "<div class=\"$class\">";
				
				echo '<a href="' . $item->url() . '">';
				echo '<figure>';
				echo '<div class="gallery">';
				echo '<img src="' . $newimage->url() . '" width="100%" />';
	
				$title =$item->title()->html();
				$class = 'gallery';
				
				if (UserIsAdmin() || UserIsSupport())
					$title .= '<small class="hidden-print"> (' . intval($time * 1000) . '&nbsp;ms)</small>';
				if (UserIsAdmin())
					$class .= ' icon-' . VisibleTo($item);
				
				echo "<figcaption class=\"$class\">$title</figcaption>";
				echo '</div><!-- /.gallery -->';
				echo '</figure>';
				echo '</a>';
				
				echo '</div><!-- /.col -->';
			}
		}
		
		echo '</div><!-- /.row -->';
	}	
	
	// Show Pagination
	if ($items->pagination()->hasPages()) {
		echo '<nav class="hidden-print">';
		
		echo '<div class="row">';
		
		echo '<div class="col-xs-6">';
		if ($items->pagination()->hasNextPage())
			echo '<a class="btn btn-default" href="' . $items->pagination()->nextPageURL() . '">&lsaquo;&nbsp;Älteres</a>';
		echo '</div><!-- /.col -->';
		
		echo '<div class="col-xs-6 text-right">';
		if ($items->pagination()->hasPrevPage())
			echo '<a class="btn btn-default" href="' . $items->pagination()->prevPageURL() . '">Neueres&nbsp;&rsaquo;</a>';
		echo '</div><!-- /.col -->';
		
		echo '</div><!-- /.row -->';
			
		echo '</nav>';
	}	
?>
<!-- /Snippet:Gallery -->

To identify the part of code, where the most time is spent, I inserted profiling code in Lines 17 and 23. The long running part is the statement $newimage = $item->image()->crop($width, $height, 15);.

And here are three examples of timings:

@robert:
What are the times, if you delete temporarily for a test:

->crop($width, $height, 15)

If this is quicker, it may be the crop function. Otherwise these files may be very big and therefore the loading of the files takes some time respectively the hard drive needs some time…

@anon77445132: The tests I did before showed, that kirby does not create the thumbs when they exists. As it should be, kirby delivers the previous generated thumbs. I think the most of the time is required by determining the file-properties by PHP. But as I told before (in previous posts) I’m not familiar with PHP, so I cannot investigate deeper. So I hope you and others can help me.

And as you can see in the graphs attached below, the images for the gallery have a size of a few KiB. The original images are much bigger in size. This is required due to show them in a detailed-view.

@anon77445132, @lukasbestle: For your information the timings at FireFox. FireFox uses the cached files! The page-generation lasts 8007 ms!