I've been having problems with intermittent huge loading times for my Elkarte forum. I host other sites on the same Nginx server, which are not affected, so it doesn't seem to be a Nginx/PHP/MySQL problem. As far as I can tell, it's Elkarte's doing.
Every few requests, when I've not made request for at least 30 seconds, the next request will take upwards of 5s to load. This doesn't happen every request - most are less than 200ms with SPDY.
I've screenshotted the output of PHP-FPM's "slowlog" below and a waterfall of the page load from Firebug.
(http://i.imgur.com/BS0ALJL.jpg)
I'm hoping someone might be able to shed some light on this, as to whether these Elkarte functions are to blame or whether it's a server issue of some sort. I can provide as much information as needed.
For "random" slowdowns I may think of two reasons:
1) a new caching of styles and scripts (javascripts),
2) a new caching of hostname lookups.
From the screen you are posting looks like the hostname lookup.
It's a bit strange the 30 seconds because the hostnames should be stored for 600 seconds, but... it may also be you are not using cache and it relies maybe on some server-side caching of the DNS record.
You may disable the hostname lookup in admin > config > server > general.
I've disabled hostname lookup, and I'll see whether it makes a difference or not over the next hour or so. Thanks.
I see the same problem actually. Hostname lookup has been disabled and just a pretty simple Apache setup.
If I haven't done a particular request for a while it takes about 4 to 5 seconds to generate the page according to Elk's own page load time output. After that it goes back to about 0.03 seconds until some unknown timeout or something.
Yes, that's exactly what I'm getting. I'm on Nginx, so it seems it's definitely an Elk issue.
I've not been seeing the issue since having disable hostname lookup, but I'll continue testing.
If you are not on a live setup you can add to your Settings.php the following line to try to get more info:
$db_show_debug = true;
it will output more debug info at the end of the page with also queries execution time and the time at which each query has been executed.
It happens to any account, or maybe just with admins?
I'm live and an admin. It is not restricted to admin pages though. I've seen it on post, who, and unread frequently.
And sadly it's not readily repeatable for me. I can't just not view a page for five minutes and know it will be slow every time.
Testing now. Throws up a lot of information. I'll keep my eye on CPU time when I get a random slow load.
What I'm trying to do is identify a more or less common pattern. For example, admins have some "security checks" done while loading the page (actually we should really do them randomly I think, it's useless to check Settings.php~ at each and every page load), so this may be a problem. Or maybe it happens only to registered members, because... dunno, maybe some ban check.
@ant59 another interesting and potentially useful is to see into "show queries" when the "time into the request" jumps. Usually the times have very small differences from the following one, but is something messes with timing and slows down something, you will notice the "jump" in time between two different queries (for example query 1 "which took 0.0002 seconds at
0.07130003 into request." and query 2 "which took 0.0003 seconds at
3.5 into request.").
Also if you have disabled the hostname look up (that based on the screen you posted before was the problem due to gethostbyaddr), have a look again at the PHP-FPM's "slowlog", it may give some more insights. ;)
Refreshing it with "Show queries" open now. I've turned hostname lookup back on, but I'm having trouble replicating the issue now. It's super-weird because this issue has been happening for weeks, but now I can't reproduce it. PHP-FPM's slowlog isn't showing anything either now :S I even ran a long test with Seige on 1 concurrent user and not a single peak over 1 second after about 5 minutes running.
I'll keep going. I've not done anything I can think of that would have fixed it.
I've seen this problem basically since installing elk beta. It's very random. I'm sure it will show up again.
Ema is there a timeout on the css/js cache that will cause it to redo them even if they haven't changed?
I understand the issue now. Elkarte is failing to find my hostname using the host or nslookup commands on the system, and is falling back to the PHP function "gethostbyaddr()" which is extremely slow. It finds many users' hostnames fine though, which is why none of my testers have come across it. Seems if you're using a common ISP, it has no problem.
I've simply completely disabled hostname requests from the admin panel. I can't think of any functionality that I lose?
Can confirm my findings: Just ran a -c10 -r10 siege test against my site with hostname requests off and not a single request showed up in PHP-FPM's slowlog.
Transactions: 100 hits
Availability: 100.00 %
Elapsed time: 26.05 secs
Data transferred: 3.39 MB
Response time: 1.84 secs
Transaction rate: 3.84 trans/sec
Throughput: 0.13 MB/sec
Concurrency: 7.05
Successful transactions: 100
Failed transactions: 0
Longest transaction: 1.31
Shortest transaction: 0.43
Not that I can see:
https://github.com/elkarte/Elkarte/blob/v1.0.1/sources/SiteCombiner.class.php#L284
only if _isStale returns true a new compilation is prepared.
In doing some digging, it looks like the daily maintenance scheduled task is emptying out the cache directory. This of course removes all the css/js hive compilations which then need to be regenerated as demanded, which can be slow.
Yup, step one of daily maintenance
// First clean out the cache.
clean_cache();
And doing that flushes the hive's etc by default ... Not sure why daily calls that TBH
So
a) remove that
or
b) add a parameter like clean_cache(full = true) and with daily call it as clean_cache(false) (with adjustments to protect the hive)
or
c) something else
I had similar issue, but I thought that it was my shared server... Then I found option Minify Javascript and CSS files, disabled it and site is loading much faster
That makes sense, it can be expensive to create those hives, so you don't want to do it daily. I think we can just change the call in maintenance to be
clean_cache('data'); and that will take care of the problem. Need to test that though.
ETA: that seems to work fine
Cool digging!
Yep, it doesn't make much sense to clean up everything.
Actually... why clean up the cache daily at all?
similar problem, 6,99 seconds to open the main page, then everything ok
Daily cache cleaning if it checks and removes really old things might make sense. But otherwise I'm not sure the point.
Made the change suggested by spuds. Will see if that clears everything up delay wise over the next few days.
Thanks for all the help here.
Great .. let us know how that works
For sure if a user / admin came to a site and triggered a hive generation it would be slow to load on that page, like seconds long. And it would be random since a bot or someone else may have triggered it before, And there are 100's of combinations, depends on settings and what action is being done. Definitely something we don't want to throw out each day :P
As to why that call is there, I can see maybe some use for the filebased cache, that could leave crud behind.
I was thinking that one option could have been to use a php script to serve the css and js to reduce the time (in the sense that loading the page an hash is computed, and passed as parameter to a file added to the head as script or link:
<link rel="stylesheet" href="http://www.elkarte.net/community/assets.php?hive=89b6b8d4ab3ed05f8104005cc092f02f475877a9;type=css?d77925ee" id="csscombined" />
<script src="http://www.elkarte.net/community/assets.php?hive=9a8029a7644dc0290120719ff63ed5eb69a260c7;type=js?252f4f7b" id="jscombinedtop"></script>
for example, but even that way, it would mean that the css and the js would appear with some 2/3 seconds of delay on the page, resulting in an unpleasant experience.
It's neat, but isn't minification and combining somewhat outside the scope of a forum engine? Surely that should fallback to the job of the actual server, using something like the PageSpeed module. I use the CloudFlare CDN with RocketLoader to do all that heavy lifting on my site.
<head>
<title>Test Poll</title>
<script type="text/javascript">
//<![CDATA[
try{if (!window.CloudFlare) {var CloudFlare=[{verbose:0,p:1415721830,byc:1,owlid:"cf",bag2:1,mirage2:0,oracle:0,paths:{cloudflare:"/cdn-cgi/nexp/dok2v=1613a3a185/"},atok:"a01dce24d5eb1332987fda69e339cc4d",petok:"48fb489887b557d46225270f19926cb4460df30d-1415723836-1800",zone:"xydre.com",rocket:"a",apps:{}}];CloudFlare.push({"apps":{"ape":"38dea9d14ab8ef67e1095ef4fc5ad7ac"}});document.write('<script type="text/javascript" src="//ajax.cloudflare.com/cdn-cgi/nexp/dok2v=919620257c/cloudflare.min.js"><'+'\/script>');}}catch(e){};
//]]>
</script>
<link rel="stylesheet" href="https://www.xydre.com/themes/xydre/css/index.css" id="index.css" />
<link rel="stylesheet" href="https://www.xydre.com/themes/default/css/prettify.css" id="prettify.css" />
<link rel="stylesheet" href="https://www.xydre.com/themes/default/css/jquery.atwho.css" id="jquery.atwho.css" />
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8" />
<meta name="viewport" content="width=device-width" />
<meta name="mobile-web-app-capable" content="yes" />
<meta name="description" content="Test Poll" />
<link rel="canonical" href="https://www.xydre.com/index.php?topic=7.0" />
<link rel="shortcut icon" sizes="140x140" href="https://www.xydre.com/themes/xydre/images/mobile.png" />
<link rel="help" href="https://www.xydre.com/index.php?action=help" />
<link rel="contents" href="https://www.xydre.com/index.php" />
<link rel="search" href="https://www.xydre.com/index.php?action=search" />
<link rel="alternate" type="application/rss+xml" title="Xydre - Gaming and Technology - RSS" href="https://www.xydre.com/index.php?action=.xml;type=rss2;limit=5" />
<link rel="alternate" type="application/rss+xml" title="Xydre - Gaming and Technology - Atom" href="https://www.xydre.com/index.php?action=.xml;type=atom;limit=5" /><link rel="next" href="https://www.xydre.com/index.php?topic=7.0;prev_next=next" /><link rel="prev" href="https://www.xydre.com/index.php?topic=7.0;prev_next=prev" />
<link rel="index" href="https://www.xydre.com/index.php?board=2.0" />
<script data-rocketsrc="//cdnjs.cloudflare.com/ajax/libs/jquery/2.1.1/jquery.min.js" type="text/rocketscript" ></script>
<script data-rocketsrc="//cdnjs.cloudflare.com/ajax/libs/foundation/5.4.7/js/foundation.min.js" type="text/rocketscript" ></script>
<script data-rocketsrc="https://www.xydre.com/themes/xydre/scripts/elk_jquery_plugins.js" id="elk_jquery_plugins.js" type="text/rocketscript" ></script>
<script data-rocketsrc="https://www.xydre.com/themes/xydre/scripts/script.js" id="script.js" type="text/rocketscript" ></script>
<script data-rocketsrc="https://www.xydre.com/themes/default/scripts/script_elk.js" id="script_elk.js" type="text/rocketscript" ></script>
<script data-rocketsrc="https://www.xydre.com/themes/xydre/scripts/theme.js" id="theme.js" type="text/rocketscript" ></script>
<script data-rocketsrc="https://www.xydre.com/themes/default/scripts/jquery.atwho.js" id="jquery.atwho.js" type="text/rocketscript" ></script>
<script data-rocketsrc="https://www.xydre.com/themes/default/scripts/jquery.caret.min.js" id="jquery.caret.min.js" type="text/rocketscript" ></script>
<script data-rocketsrc="https://www.xydre.com/themes/default/scripts/mentioning.js" id="mentioning.js" type="text/rocketscript" ></script>
<script data-rocketsrc="https://www.xydre.com/themes/default/scripts/topic.js" id="topic.js" type="text/rocketscript" ></script>
<script type="text/rocketscript" ><!-- // --><![CDATA[
$(document).ready(function () {
for (var i = 0, count = all_elk_mentions.length; i < count; i++)
all_elk_mentions[i].oMention = new elk_mentions(all_elk_mentions[i].oOptions);
});
$(document).ready(function() {
$().linkifyvideo(oEmbedtext);
});
var elk_theme_url = 'https://www.xydre.com/themes/xydre',
elk_default_theme_url = 'https://www.xydre.com/themes/default',
elk_images_url = 'https://www.xydre.com/themes/xydre/images',
elk_smiley_url = 'https://www.xydre.com/smileys',
elk_scripturl = 'https://www.xydre.com/index.php',
elk_iso_case_folding = false,
elk_charset = "UTF-8",
elk_session_id = 'REDACTED',
elk_session_var = 'REDACTED',
elk_member_id = 1,
ajax_notification_text = 'Loading...',
ajax_notification_cancel_text = 'Cancel',
help_popup_heading_text = 'A little lost? Let me explain:',
use_click_menu = false,
todayMod = 2,
notification_topic_notice = 'Are you sure you wish to enable notification of new replies for this topic?',
sendtopic_cancel = 'Cancel',
sendtopic_back = 'Back',
sendtopic_close = 'Close',
sendtopic_error = 'An error has occurred, <a hr'+'ef="{href}">please click here to try again<' + '/a>.',
required_field = 'This is a required field.';
// ]]></script>
<!--[if lt IE 9]>
<script src="//html5shim.googlecode.com/svn/trunk/html5.js"></script>
<![endif]-->
</head>
I don't mean to be negative, I'm just curious.
I think you will find, for a lot of users, that is going to be to complicated, so we wanted to provide something that was a one click affair. Nothing else to sign up for, nothing required, etc. Mods, themes, etc are just taken care of by the core right now.
What you have, using a CDN, is certainly the best way to go. I've thought about writing an addon that would do just that (and to verify that we have the hooks in place to do that), meaning to build out the CDN js/css in place of the built in minimizing.
I'm not sure what to do TBH ... its a one time slowdown and then its done (but it sucks when its you). One thought I had was to have a task that gets kicked off once you click that button to start building min files of the js/css then the combiner would find those and use them in the hive with no delay. Could even ship 1.02 with min files and until you change a file they would be good to use.
Ah, fair enough. It's certainly quick and easy :)
What about pages requiring multiple scripts/stylesheets? Doesn't minimizing those in source defeat the purpose, since you've then got to combine and re-minimize them anyway?
The only way to avoid the need for combining sheets and scripts is to use SPDY, which not all web servers can support.
Just wanted to report that since changing the clear cache call to have the 'data' argument I've not seen the random slowdowns. Will continue to watch.
Also I do appreciate the ability to have Elk combine and minify things without any external sites.
As to pre-generating the cached files what about a script that calls the predictably most common pages that random visitors are likely to see. Forum index, category, board, topic, registration, profile, recent topics. Ones that would show up for new users who might be especially put off by a site that seems slow to respond up front. Once people are registered infrequent slowdowns that would occur after the site was modified likely would not drive them away. And even for them you could probably handle most of it with the post page, pm pages, and new / unread topics.
It seems that disabling hostname lookups was the cure. Since then, I've had no major slowdowns from script delay. The only thing to show up in the "slowlog" is BadBehaviour, which is a fair trade-off. Not using Elkarte minification or combiner.
Good to hears the source(s) of the slowdowns seem to have been found :D One we can fix, one not sure we can do anything other than what we have now (checkbox to disable). Anyone know why those hostname lookups are slow on some systems? Is there an alternative other than disable?
If it helps, I narrowed the issue down to PHP's built-in gethostbyaddr() function here:
https://github.com/elkarte/Elkarte/blob/master/sources/Subs.php#L3191
The system calls above are instant. But using the PHP method seems to cause long delays.
Maybe this is a result that could be cached?
It seems after a little bit of reading that some people are saying it causes the script to slow when an IP isn't resolved.
Reading around on the web it kind of confirms that gethostbyaddr is slow or can be slow and there isn't much to do about it.
@IchBin cache is already used, though is not really always useful in that case, because if the IP is not present (and the likelihood it is not is far greater than the contrary) in the cache we have to resolve it to get the hostname. ;)
I understand that it might not be useful in the case where the IP is not present. But in the case when a lookup can take a significant amount of time to actually obtain the IP, this could save the time in that case for the next time it looks up that same IP that doesn't resolve quickly. But if cache is already used for this, and the issue really is not being to find the IP at all, there's not much that can be done about that. lol