Skip to main content
Slow loading profile page [was: Re: Largest ElkArte boards?] Started by Acido · · Read 19850 times 0 Members and 1 Guest are viewing this topic. previous topic - next topic - Topic derived from Largest ElkArte boards?

Slow loading profile page [was: Re: Largest ElkArte boards?]

Quote from: Joshua Dickerson – Let us know if there is anything we can do to make it easier (besides writing a custom importer).

Ran into an issue, not sure if its related to the import or not though.

When loading profile of logged in user, sometimes the script just runs forever (or rather until php times out) talking about just ?action=profile

There are no errors in php error log nor the forum error logs, so a bit at a loss as to the cause. If i load another user profile and then my own it works again (but takes around 3 seconds to load the first time) for awhile only to do the same again after about an hour. No addons installed and happens on the default theme as well as the one I'm currently creating.

Edit: After a bit more testing, if i browse around the forum a little bit then load my profile again it loads but takes anywhere from 1.5-3 seconds to load, after which it loads instantly until i do something else then load it again and it will take the same 1.5-3 seconds to load again. Any other action that i have tried loads the page in ~0.05 seconds only the profile page takes this long. Have tried disabling hostname lookout but didn't change anything.
Last Edit: January 17, 2016, 12:01:34 am by Acido

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #1

Cache enabled?

 

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #3

I haven't run into any extended loading on Hydrogenaudio, other than caching new style sheets or scripts if changes were made server side. Currently using the opcache module, and PECL Memcached module with memcached running with a 64MB buffer. Maybe it would help me to know what exactly the caching serves to buffer for the loading.

I'm also using database sessions, which was pulling up some errors before, because of some malformed code that assumed that $db->insert returned a value. Oh crud, that reminds me, that's more code I need to make a pull request for. E: Never mind, development already does it even better than I did, so I've pulled the changes from development into my release version.
Last Edit: January 17, 2016, 12:54:54 am by kode54

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #4

Quote from: kode54 – I haven't run into any extended loading on Hydrogenaudio, other than caching new style sheets or scripts if changes were made server side. Currently using the opcache module, and PECL Memcached module with memcached running with a 64MB buffer. Maybe it would help me to know what exactly the caching serves to buffer for the loading.

I'm also using database sessions, which was pulling up some errors before, because of some malformed code that assumed that $db->insert returned a value. Oh crud, that reminds me, that's more code I need to make a pull request for. E: Never mind, development already does it even better than I did, so I've pulled the changes from development into my release version.

Didn't use a cache module, just file based caching and entirely off, both producing the same behavior. But i find it hard to believe the problem lies with caching when the problem only occurs on loading the profile and not on anything else. I am using database sessions as well.

But since you are not experiencing any load issues I'm guessing the problem is somewhere with my import of member profiles (or you simply don't experience the underlying problem since you have a working cache) I'll look into it some more, just not sure where to start looking for the problem as there are no errors being reported from neither php logs or forum logs. But suppose should be able to debug easier now i know exactly how to reproduce it. Every time i enter a few topics then proceeds to load up the user profile, it takes around 1.5-3 seconds to load it.
Last Edit: January 17, 2016, 01:32:27 am by Acido

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #5

Do you have the option to minify js and css on?
It doesn't sound like that, but worth a try.
Bugs creator.
Features destroyer.
Template killer.

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #6

Quote from: emanuele – Do you have the option to minify js and css on?
It doesn't sound like that, but worth a try.

No that option is toggled off.

Trace from php slow log if that helps:

[0x00007fb79c029628] elk_main() /var/www/test_fmfreaks/index.php:145
[0x00007fb79c02ad90] dispatch() /var/www/test_fmfreaks/index.php:217
[0x00007fb79c02b838] action_index() /var/www/test_fmfreaks/sources/SiteDispatcher.class.php:306
[0x00007fb79c02c0b0] callMenu() /var/www/test_fmfreaks/sources/controllers/Profile.controller.php:680
[0x00007fb79c031470] action_summary() /var/www/test_fmfreaks/sources/subs/Menu.subs.php:389
[0x00007fb79c031708] load_user_posts() /var/www/test_fmfreaks/sources/controllers/ProfileInfo.controller.php:295
[0x00007fb79c037460] query() /var/www/test_fmfreaks/sources/subs/Profile.subs.php:2947
[0x00007fb79c037bf0] mysqli_query() /var/www/test_fmfreaks/sources/database/Db-mysql.class.php:406
script_filename = /var/www/test_fmfreaks/index.php
[17-Jan-2016 15:29:05]  [pool www] pid 6298

As far as i can see from this the delay happens on load_user_posts() Which makes me wonder why its loading up all the user posts on summary to begin with as its loading them again if you actually click view posts inside the profile causing the same delay again.

[0x00007fb79c0295b8] elk_main() /var/www/test_fmfreaks/index.php:145
[0x00007fb79c02ad20] dispatch() /var/www/test_fmfreaks/index.php:217
[0x00007fb79c02b7c8] action_index() /var/www/test_fmfreaks/sources/SiteDispatcher.class.php:306
[0x00007fb79c02c040] callMenu() /var/www/test_fmfreaks/sources/controllers/Profile.controller.php:680
[0x00007fb79c031400] action_showPosts() /var/www/test_fmfreaks/sources/subs/Menu.subs.php:389
[0x00007fb79c031698] load_user_posts() /var/www/test_fmfreaks/sources/controllers/ProfileInfo.controller.php:508
[0x00007fb79c035160] query() /var/www/test_fmfreaks/sources/subs/Profile.subs.php:2947
[0x00007fb79c0358f0] mysqli_query() /var/www/test_fmfreaks/sources/database/Db-mysql.class.php:406
script_filename = /var/www/test_fmfreaks/index.php
[17-Jan-2016 15:38:12]  [pool www] pid 6291

It's interesting though why this query takes so long to load while there is no delay loading the posts on the other parts of the forum, it would access the same table with 1.1 million rows.
Last Edit: January 17, 2016, 09:56:53 am by Acido

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #7

I split up the discussion for better organization. ;)

The reason for loading the messages is for the "recent activity" tab in the profile summary.
It's a kind of "stop gap", the content of the tab is meant to be loaded via ajax, though for the time being has been put in-line.

The query is rather slow, and in some cases is even repeated twice (one time with a limit to reduce the table scan and if it doesn't find enough entries is repeated without the limiting condition).
Actually this may even be one of the reasons.

Since you are using a testing forum, would you mind adding:
Code: [Select]
$db_show_debug = true;
to your Settings.php?
Then open the profile page and take a look to the queries at the end of the page, see if there is one or two that start with:
Code: [Select]
			SELECT
b.id_board, b.name AS bname,
c.id_cat, c.name AS cname,
m.id_topic, m.id_msg, m.body, m.smileys_enabled, m.subject, m.poster_time, m.approved,
t.id_member_started, t.id_first_msg, t.id_last_msg

Thanks! :D
Bugs creator.
Features destroyer.
Template killer.

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #8

Quote from: emanuele – I split up the discussion for better organization. ;)

The reason for loading the messages is for the "recent activity" tab in the profile summary.
It's a kind of "stop gap", the content of the tab is meant to be loaded via ajax, though for the time being has been put in-line.

The query is rather slow, and in some cases is even repeated twice (one time with a limit to reduce the table scan and if it doesn't find enough entries is repeated without the limiting condition).
Actually this may even be one of the reasons.

Since you are using a testing forum, would you mind adding:
Code: [Select]
$db_show_debug = true;
to your Settings.php?
Then open the profile page and take a look to the queries at the end of the page, see if there is one or two that start with:
Code: [Select]
			SELECT
b.id_board, b.name AS bname,
c.id_cat, c.name AS cname,
m.id_topic, m.id_msg, m.body, m.smileys_enabled, m.subject, m.poster_time, m.approved,
t.id_member_started, t.id_first_msg, t.id_last_msg

Thanks! :D

Yup there is such a query. Sometimes php times out when loading the script entirely so it never loads at all, but i have been unable to reproduce when this happens, usually as i have said it will just take around 1.5-3 seconds after i browse around the forum for awhile then load up profile.

Page created in 1.518 seconds with 18 queries.
System: Linux fmfreaks.dk 3.14.14-gentoo #2 SMP Sun Aug 10 03:31:21 CEST 2014 x86_64
Server Load: 0.07375
Script Memory Usage: 6.89MB
Script CPU Time (user/system): 1.038 / 0.41
Browser ID: firefox (is_firefox43, is_firefox, is_gecko)
Templates: 6: index (FmFreaks), Profile (default), GenericMessages (default), GenericMenu (default), ProfileInfo (default), GenericMessages (default).
Sub templates: 11: html_above, body_above, admin_warning_above, generic_menu_dropdown_above, profile_above, action_summary, profile_below, generic_menu_dropdown_below, admin_warning_below, body_below, html_below.
Language files: 4: index+Addons.english (FmFreaks), Profile+Drafts.english (FmFreaks), Who.english (FmFreaks), index.english (FmFreaks).
Style sheets: 4: index.css(FmFreaks), font-awesome.min.css(FmFreaks), _fmfreaks/index_fmfreaks.css(FmFreaks), custom.css(FmFreaks).
Scripts: 5: elk_jquery_plugins.js(default), script.js(default), script_elk.js(default), theme.js(FmFreaks), profile.js(default).
Hooks called: 47 (integrate_verify_user, integrate_avatar, integrate_user_info, integrate_simple_actions, integrate_init_theme, integrate_theme_include, integrate_load_theme, integrate_pre_log_stats, integrate_action_frontpage, integrate_actions, integrate_action_profile_before, integrate_load_member_data, integrate_add_member_data, integrate_avatar, integrate_member_context, integrate_profile_areas, integrate_profile_summary, integrate_whos_online_allowed, integrate_whos_online, integrate_pre_parsebbc, integrate_bbc_codes, integrate_post_parsebbc, integrate_pre_parsebbc, integrate_post_parsebbc, integrate_pre_parsebbc, integrate_post_parsebbc, integrate_pre_parsebbc, integrate_post_parsebbc, integrate_pre_parsebbc, integrate_post_parsebbc, integrate_pre_parsebbc, integrate_post_parsebbc, integrate_pre_parsebbc, integrate_post_parsebbc, integrate_pre_parsebbc, integrate_post_parsebbc, integrate_pre_parsebbc, integrate_post_parsebbc, integrate_pre_parsebbc, integrate_post_parsebbc, integrate_load_custom_profile_fields, integrate_action_profile_after, integrate_menu_buttons, pre_css_output, pre_javascript_output, integrate_basic_url_replacement, pre_javascript_output)
Files included: 40 - 1157KB. (./index.php, ./Settings.php, ./db_last_error.php, ./sources/QueryString.php, ./sources/Session.php, ./sources/Subs.php, ./sources/Errors.php, ./sources/Logging.php, ./sources/Load.php, ./sources/subs/Cache.subs.php, ./sources/Security.php, ./sources/BrowserDetector.class.php, ./sources/ErrorContext.class.php, ./sources/subs/Util.class.php, ./sources/subs/TemplateLayers.class.php, ./sources/Action.controller.php, ./sources/Request.php, ./sources/database/Database.subs.php, ./sources/database/Db.php, ./sources/database/Db-mysql.class.php, ./themes/FmFreaks/index.template.php, ./themes/FmFreaks/languages/english/index.english.php, ./themes/default/languages/english/Addons.english.php, ./sources/SiteDispatcher.class.php, ./sources/controllers/Profile.controller.php, ./themes/default/languages/english/Profile.english.php, ./themes/default/languages/english/Drafts.english.php, ./themes/default/Profile.template.php, ./themes/default/GenericMessages.template.php, ./sources/subs/Menu.subs.php, ./sources/subs/Profile.subs.php, ./themes/default/GenericMenu.template.php, ./sources/controllers/ProfileInfo.controller.php, ./themes/default/ProfileInfo.template.php, ./sources/subs/Who.subs.php, ./themes/default/languages/english/Who.english.php, ./sources/subs/Topic.subs.php, ./sources/subs/Bans.subs.php, ./sources/subs/Attachments.subs.php, ./sources/subs/Moderation.subs.php)
Tokens: get-profile-aa1, get-profile-aa2449, post-profile-ac1, post-profile-th1, post-profile-fp1, post-admin-lang.

Queries used: 18.
..


         SELECT
            b.id_board, b.name AS bname,
            c.id_cat, c.name AS cname,
            m.id_topic, m.id_msg, m.body, m.smileys_enabled, m.subject, m.poster_time, m.approved,
            t.id_member_started, t.id_first_msg, t.id_last_msg
         FROM fmf_messages AS m
            INNER JOIN fmf_topics AS t ON (t.id_topic = m.id_topic)
            INNER JOIN fmf_boards AS b ON (b.id_board = t.id_board)
            LEFT JOIN fmf_categories AS c ON (c.id_cat = b.id_cat)
         WHERE m.id_member = 1
            AND 1=1
         ORDER BY m.id_msg DESC
         LIMIT 0, 10
   in .../sources/subs/Profile.subs.php line 2947, which took 1.45524287 seconds at 0.0474999 into request.

      SELECT COUNT(*)
      FROM fmf_topics AS t
      WHERE t.id_member_started = 1
   in .../sources/subs/Profile.subs.php line 2821, which took 0.00034809 seconds at 1.50849986 into request.

         SELECT
            b.id_board, b.name AS bname,
            c.id_cat, c.name AS cname,
            t.id_member_started, t.id_first_msg, t.id_last_msg, t.approved,
            m.body, m.smileys_enabled, m.subject, m.poster_time, m.id_topic, m.id_msg
         FROM fmf_topics AS t
            INNER JOIN fmf_boards AS b ON (b.id_board = t.id_board)
            LEFT JOIN fmf_categories AS c ON (c.id_cat = b.id_cat)
            INNER JOIN fmf_messages AS m ON (m.id_msg = t.id_first_msg)
         WHERE t.id_member_started = 1
            AND 1=1
         ORDER BY t.id_first_msg DESC
         LIMIT 0, 10
   in .../sources/subs/Profile.subs.php line 3012, which took 0.00056481 seconds at 1.50900006 into request.
Last Edit: January 17, 2016, 11:20:51 am by Acido

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #9

If you click on the query, it should open up a new window and show the "EXPLAIN" (a table under the query), could you please try that and post here the results?
Bugs creator.
Features destroyer.
Template killer.

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #10

SELECT
  b.id_board, b.name AS bname,
  c.id_cat, c.name AS cname,
  m.id_topic, m.id_msg, m.body, m.smileys_enabled, m.subject, m.poster_time, m.approved,
  t.id_member_started, t.id_first_msg, t.id_last_msg
FROM fmf_messages AS m
  INNER JOIN fmf_topics AS t ON (t.id_topic = m.id_topic)
  INNER JOIN fmf_boards AS b ON (b.id_board = t.id_board)
  LEFT JOIN fmf_categories AS c ON (c.id_cat = b.id_cat)
WHERE m.id_member = 1
  AND 1=1
ORDER BY m.id_msg DESC
LIMIT 0, 10
in .../sources/subs/Profile.subs.php line 2947, which took 1.56765699 seconds at 0.0474999 into request.
id select_type table type possible_keys key key_len ref rows Extra
1 SIMPLE b ALL PRIMARY 162 Using temporary; Using filesort
1 SIMPLE c eq_ref PRIMARY PRIMARY 1 betafmfreaks.b.id_cat 1
1 SIMPLE t ref PRIMARY,id_board,last_message_sticky,board_news id_board 2 betafmfreaks.b.id_board 1
1 SIMPLE m ref topic,id_member,participation,show_posts,id_topic,id_member_msg,current_topic,related_ip id_topic 3 betafmfreaks.t.id_topic 1 Using where

Screenshot for better formatting of the table:
Last Edit: January 17, 2016, 11:49:46 am by Acido

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #11

I don't see any reason why it is taking that long. Those joins can be left or inner and be fine either way. Filesort/temp table on a table with 162 rows is nothing. That can actually just be a MySQL optimization.

I think this is grasping at straws, but can you try this query on its own:
Code: [Select]
SELECT
  m.id_topic, m.id_msg, m.body, m.smileys_enabled, m.subject, m.poster_time, m.approved,
  t.id_member_started, t.id_first_msg, t.id_last_msg
  b.id_board, b.name AS bname,
  c.id_cat, c.name AS cname,
FROM fmf_messages AS m
  LEFT JOIN fmf_topics AS t ON (t.id_topic = m.id_topic)
  LEFT JOIN fmf_boards AS b ON (b.id_board = t.id_board)
  LEFT JOIN fmf_categories AS c ON (c.id_cat = b.id_cat)
WHERE m.id_member = 1
ORDER BY m.id_msg DESC
LIMIT 0, 10

Can you keep browsing your forum and keep trying to reproduce it to make sure it is that query. It might be another query that locks the tables and you're just getting the effect on that query.

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #12

Quote from: Joshua Dickerson – I don't see any reason why it is taking that long. Those joins can be left or inner and be fine either way. Filesort/temp table on a table with 162 rows is nothing. That can actually just be a MySQL optimization.

I think this is grasping at straws, but can you try this query on its own:
Code: [Select]
SELECT
  m.id_topic, m.id_msg, m.body, m.smileys_enabled, m.subject, m.poster_time, m.approved,
  t.id_member_started, t.id_first_msg, t.id_last_msg
  b.id_board, b.name AS bname,
  c.id_cat, c.name AS cname,
FROM fmf_messages AS m
  LEFT JOIN fmf_topics AS t ON (t.id_topic = m.id_topic)
  LEFT JOIN fmf_boards AS b ON (b.id_board = t.id_board)
  LEFT JOIN fmf_categories AS c ON (c.id_cat = b.id_cat)
WHERE m.id_member = 1
ORDER BY m.id_msg DESC
LIMIT 0, 10

Can you keep browsing your forum and keep trying to reproduce it to make sure it is that query. It might be another query that locks the tables and you're just getting the effect on that query.

Manual query results in an error:
#1064 - You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '.id_board, b.name AS bname, c.id_cat, c.name AS cname, FROM fmf_messages AS m ' at line 4

It is this query for sure, its the one the debug info shows taking >1.5seconds every time, and it happens every single time i browse around for a few seconds then load the profile.

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #13

Code: [Select]
SELECT
  m.id_topic, m.id_msg, m.body, m.smileys_enabled, m.subject, m.poster_time, m.approved,
  t.id_member_started, t.id_first_msg, t.id_last_msg,
  b.id_board, b.name AS bname,
  c.id_cat, c.name AS cname
FROM fmf_messages AS m
  LEFT JOIN fmf_topics AS t ON (t.id_topic = m.id_topic)
  LEFT JOIN fmf_boards AS b ON (b.id_board = t.id_board)
  LEFT JOIN fmf_categories AS c ON (c.id_cat = b.id_cat)
WHERE m.id_member = 1
ORDER BY m.id_msg DESC
LIMIT 0, 10

Re: Slow loading profile page [was: Re: Largest ElkArte boards?]

Reply #14

Showing rows 0 - 9 ( 10 total, Query took 0.0006 sec) [id_msg: 1223438 - 1199941]

Edit: Okay now I'm confused. Was putting it off looking into this situation more and started working on some other stuff and now all of a sudden it doesn't happen anymore. It's still not blazingly fast (load times around 0.1 seconds) but at least no longer takes full seconds. Have no idea what changed and why it doesn't happen anymore. I did change the inner joins to left for testing and forgot to change them back, but that should have no influence.

But I guess as Joshua suggested could be some table locks, still strange that it stopped doing it suddenly, will monitor the situation if it changes again.
Last Edit: January 18, 2016, 12:03:14 am by Acido