Slow page loading after upgrade to 2.2.1

[tamsrud]

After upgrading a couple of sites to 2.2.1, it is some sort of lag on first load that I cant identify.

When I first visit a site, it takes 3 second for the page to show. When reloading it loads at once.

When executing the MySQL commands directly on the server it respons as usual.

If waiting a couple of minutes, it is back to the 3 second wait.

Debug shows:

Debug: (0.023953) - (net usage: 1650960) - (peak: 2013208)
SELECT item_id,url FROM cms_module_lisevideoer_item WHERE url != ''
Debug: (0.026259) - (net usage: 1748224) - (peak: 2110472)
End of Loading Modules
Debug: (0.028274) - (net usage: 1773584) - (peak: 2135832)
SELECT * FROM cms_mod_cmsjobmgr WHERE start < UNIX_TIMESTAMP() AND created < UNIX_TIMESTAMP() ORDER BY errors ASC,created ASC LIMIT 1
Debug: (0.028649) - (net usage: 1779880) - (peak: 2142128)
SELECT * FROM cms_content WHERE content_id = 4 LIMIT 1
Debug: (0.029817) - (net usage: 1875968) - (peak: 2238216)
UPDATE cms_siteprefs SET sitepref_value = 1498562490 WHERE sitepref_name = 'CmsJobManager_mapi_pref_last_async_trigger'
Debug: (3.03503) - (net usage: 1811816) - (peak: 2238216)
Initialize Smarty
Debug: (3.035046) - (net usage: 1811976) - (peak: 2238216)
Done Initialiing Smarty

On reload is shows:

Debug: (0.045961) - (net usage: 1650928) - (peak: 2013176)
SELECT item_id,url FROM cms_module_lisevideoer_item WHERE url != ''
Debug: (0.048336) - (net usage: 1748192) - (peak: 2110440)
End of Loading Modules
Debug: (0.05332) - (net usage: 1750120) - (peak: 2112368)
Initialize Smarty
Debug: (0.053334) - (net usage: 1750280) - (peak: 2112528)
Done Initialiing Smarty

So I think it has something to do with whats happening between Loading Modules and Initialize Smarty.

Im also a bit confused with the timestamp in the log. Does this mean it was a lag before the "Initialize Smarty" or after?

Site running on private VPS with Ubuntu 16.04 (apache/2.4.18) and MySQL 5.7.18 and PHP 7.0.18-0ubuntu0.16.04.1

Any idea whats happening?

[tamsrud]

Does anyone have a similar problem?
It happens on all sites using 2.2.1, but none with prior versions.

It a big problem since it degrades the quality of the sites when it suddnelyg has a 3 second delay on load.

Im not shure how to debug this further, based on the log posted.

[Rolf]

I haven't got page load problems at my sites... at least I did not notice it
I.e. https://welovecmsms.com/ and https://www.cmscanbesimple.org/ and I have other even larger websites without issues.
But it can be a third party module that does this and i dont use that particular one...

[tamsrud]

Tested on multiple sites, and also on a fresh install without third-party-modules, but with same problem.

It could be something with my server. It has low load and plenty of memory and diskspace available, so cannot point to a specific problem.

But, regarding the log I posted. Where is the delay?
Is it in the "Initialize Smarty"? Or happening before that?

I have made a test-site to debug this problem, a fresh install without any modifications at all (no modules or edited templates): http://test.ekhweb.no Let it rest for 5 minutes, and then it will use 3 extra seconds to process the page. On reload it comes in a blink.

[velden]

I guess the 'CmsJobManager' could be a starting point.

I don't know much about it but it does, well, managing jobs which should run in the background. Typically it needs someone to visit the website to start checking for jobs and processing (parts of) them.

Intervals can be used so that could explain why it takes a few minutes to see this behavior again. For a fresh install it may be the search index being built (I'm just guessing btw).

[velden]

BTW: I would expect some lines in the CMSMS admin log about the processed jobs. They, however, don't show duration.

And existing jobs (or failed jobs) are displayed in Admin >> Background Job Manager

[tamsrud]

Thanks for feedback. I found the problem due to a warning that showed up now:
Warning: fsockopen(): unable to connect to test.ekhweb.no:80 (Connection timed out) in /var/www/clients/client1/web234/web/modules/CmsJobManager/CmsJobManager.module.php on line 296

And the command on this does have a timeout on 3 seconds.

The reason this failed, was because this tries to reach the public ip. While the server didnt remap this to the local ip, so it failed.

When remapping public-ip to local-ip, the problem was resolved.

[tamsrud]

But it still uses 1 second more when triggering the CmsJobManager. Since most of my sites is small, this would mean it is triggered almost every time a user enters the site, and the site feels "slow".

Should it be able to adjust the refresh rate for the CmsJobManager? Or could it be optimized when there is nothing in qeue? It uses roughly 1 second extra even when it "Found nothing to do".

[calguy1000]

The async processing is triggered at most every 3 minutes. It is asynchronous. i.e: the jobs are processed by a separate HTTP request. There is a 3-second timeout on the fsockopen command that establishes the connection.

If you are having problems with HTTP requests coming from your webserver and going to your webserver then I suppose that you are also going to have problems with ajax requests and various other functionality.

It sounds more like a problem with your host configuration than with CMSMS.

[tamsrud]

As said, I have fixed the problem with the HTTP requests with adjustments on the server. But it still uses 1 second extra to initiate the async processing.

Regarding ajax calls, they have never been a problem, since they are sent from the client. The problems started with version 2.2 and the CmsJobManager.

[calguy1000]

As said, I have fixed the problem with the HTTP requests with adjustments on the server. But it still uses 1 second extra to initiate the async processing

.

That still implies a server issue of some sort. DNS lookup issues, or routing or firewalls or whatever.

In many regular hosting environments, and in my test setup even on the requests that initiate fsockopen (and I have tested many many times). the request is finished in less than 0.1 seconds

[tamsrud]

I will do some more debuging on ny servers regarding this. I now know where to look,, so I should be aboe to pin point it.

Thanks for feedback. I will report if I find something.

[tamsrud]

I have done a bit more testing today, and tried to pin point the lag. After adjusting the server yesterday, most request finish in less than 0.1 second.

But when there is a job in qeue (usualy News\CreateDraftAlertTask since i test on a fresh install) it uses 1.1 second extra to process this job.

It is the "$data = fgets($fp);" in "public function trigger_async_processing()" in CmsJobManager.module.php that uses all the extra time.

When using fgets( I suppose its not completely async, since we have to wait for the response stream.

When commenting out the fgets( line, the lag is gone, and processing finishes in 0.14 seconds.

As I see it, the only reason for fgets( is to get the response code.

I suggest that fgets( only runs when debugging is turned on to eliminate this problem.

I also think that the fsockopen( could at least timeout on 1 second instead of 3. In any normal situation it should repond in 0.1 second. (In all my tests the fsockopen( is finished in 1 ms).

[calguy1000]

You are still looking for a CMSMS problem, but it's a server problem.

The CMSMS async processing code is tricky, in that it immediately returns a 'connection close' header, flushes output and keeps processing in the backgound (asynchronously).

So the fgets should not be waiting at all in a normal working environment.

[tamsrud]

It might be a server problem, but I cant figure it out.

I have searched a lot for similar problems, and your last comment helped me on the way (First 12 lines of action.process.php). I have been looking into the PHP and Apache settings for what is keeping the connection alive. But still no resolution.

I have now tested to add a sleep(3); on line 79 in action.process.php to debug further. And then front end page loading also uses 3 seconds every time. - http://test.ekhweb.no

So on my setup, its certain that its not working async.

I have been searching for reasons for why the server doesnt close the connection when recieving the "Connection: close" header. But I cant seem to find that it should. Every place I find something about it, it says that this is only a message to the client that he should close the connection (and NOT KeepAlive).

https://stackoverflow.com/questions/556 ... ing-script
https://stackoverflow.com/questions/138 ... tion-early

Thanks for the help so far. But now Im not sure were else to look.