Moodle
  1. Moodle
  2. MDL-24638

Poor performance due to excessive queries

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 1.9.8
    • Fix Version/s: 1.9.10
    • Component/s: Forum
    • Labels:
      None
    • Database:
      MySQL
    • Affected Branches:
      MOODLE_19_STABLE
    • Fixed Branches:
      MOODLE_19_STABLE
    • Rank:
      36110

      Description

      On Moodle 1.9.8, when viewing a faculty profile (while logged in as Admin), if I view the faculty member's forum posts, the page takes quite awhile to load.
      Once it has loaded, these are the performance stats in the footer:
      12.830042 secs
      RAM: 17.1MB
      RAM peak: 29.5MB
      Included 111 files
      DB queries 13051
      Log writes 1
      Load average: 0.40

      Note that DB queries shows 13,051... It took this page 13s to generate (considering the # of queries, that's actually impressive), and uses 30mb of ram, all to display 5 forum posts, with a max of 2 pages in pagination.

      This is quite shocking. The raw number of queries here, is something that I haven't seen since the days of PHP-Nuke popularity (which was very poor code indeed).

      Why would thousands of queries be needed to simply pull up what posts a person has made?
      I can understand additional queries being needed if there are a large number of courses (we have ~100 courses in our installation), but this suggests very poor design.

      1. 2010101500-MDL-24638.patch
        2 kB
        Aparup Banerjee

        Activity

        Hide
        Martin Dougiamas added a comment -

        Indeed something very wrong is going on there, thanks for the report.

        Apu, can you see if you can duplicate this? If not, you may need more info from Jonathan about their set up (eg, it might depend on number of posts, or forums, or courses, or users etc, or whether some caching is on or not)

        Show
        Martin Dougiamas added a comment - Indeed something very wrong is going on there, thanks for the report. Apu, can you see if you can duplicate this? If not, you may need more info from Jonathan about their set up (eg, it might depend on number of posts, or forums, or courses, or users etc, or whether some caching is on or not)
        Hide
        Aparup Banerjee added a comment -

        Hi Jonathan,
        thanks for the extra info, I'm still trying to replicate this , so far unsuccessful.

        i did notice that my included files are usually around the 50-52 mark for the page.
        Are there any changes to the installation (plugins?) that may have extra effects on this page?

        Show
        Aparup Banerjee added a comment - Hi Jonathan, thanks for the extra info, I'm still trying to replicate this , so far unsuccessful. i did notice that my included files are usually around the 50-52 mark for the page. Are there any changes to the installation (plugins?) that may have extra effects on this page?
        Hide
        Aparup Banerjee added a comment -

        Hi Jonathan,
        a few more queries :
        Do you have any filters enabled ?
        Is there by any chance any custom code in the installation?

        Show
        Aparup Banerjee added a comment - Hi Jonathan, a few more queries : Do you have any filters enabled ? Is there by any chance any custom code in the installation?
        Hide
        Aparup Banerjee added a comment -

        ok i'm tending towards replicating this performance issue,
        a couple thousand discussions created (with no post yet) gets me
        2.958336 secs
        RAM: 32MB
        RAM peak: 39.9MB
        Included 52 files
        DB queries 1492
        Log writes 1
        ticks: 296
        user: 130 sys: 11 cuser: 0 csys: 0 Load average: 0.94
        Record cache hit/miss ratio : 0/0

        most queries coming from through trace.
        /lib/dmllib.php:682</lib/dmllib.php:481</lib/datalib.php:1679</mod/forum/lib.php:1767</mod/forum/user.php:97<

        /mod/forum/lib.php:1767 $cm = get_coursemodule_from_instance('forum', $forumid);
        mod/forum/lib.php: forum_search_posts() would have to be improved somehow.

        Show
        Aparup Banerjee added a comment - ok i'm tending towards replicating this performance issue, a couple thousand discussions created (with no post yet) gets me 2.958336 secs RAM: 32MB RAM peak: 39.9MB Included 52 files DB queries 1492 Log writes 1 ticks: 296 user: 130 sys: 11 cuser: 0 csys: 0 Load average: 0.94 Record cache hit/miss ratio : 0/0 most queries coming from through trace. /lib/dmllib.php:682</lib/dmllib.php:481</lib/datalib.php:1679</mod/forum/lib.php:1767</mod/forum/user.php:97< /mod/forum/lib.php:1767 $cm = get_coursemodule_from_instance('forum', $forumid); mod/forum/lib.php: forum_search_posts() would have to be improved somehow.
        Hide
        Aparup Banerjee added a comment -

        thanks Jonathan,
        a quick

        SELECT distinct( substr(sql1,1,45)) as qry , count as amt, sql1 as example_query
        FROM adodb_logsql a
        group by qry
        order by amt desc
        limit 5

        shows some example culprits:
        1) 2541 SELECT id, content, name FROM loom_label WHERE id = '264' LIMIT 100
        2) 1996 SELECT id, popup, reference, type, name FROM loom_resource WHERE id = '1288' LIMIT 100
        3) 1475 SELECT cm.*, m.name, md.name as modname FROM loom_course_modules cm, loom_modules md, loom_forum m WHERE cm.instance = m.id AND md.name = 'forum' AND md.id = cm.module AND m.id = 185 LIMIT 100
        4) 680 SELECT * FROM loom_context WHERE contextlevel = '10' LIMIT 1
        5) 364 SELECT id, assignmenttype, name FROM loom_assignment WHERE id = '642' LIMIT 100

        i'm working on a patch to reduce the

        {course_modules}

        queries by lumping some queries together..

        Show
        Aparup Banerjee added a comment - thanks Jonathan, a quick SELECT distinct( substr(sql1,1,45)) as qry , count as amt, sql1 as example_query FROM adodb_logsql a group by qry order by amt desc limit 5 shows some example culprits: 1) 2541 SELECT id, content, name FROM loom_label WHERE id = '264' LIMIT 100 2) 1996 SELECT id, popup, reference, type, name FROM loom_resource WHERE id = '1288' LIMIT 100 3) 1475 SELECT cm.*, m.name, md.name as modname FROM loom_course_modules cm, loom_modules md, loom_forum m WHERE cm.instance = m.id AND md.name = 'forum' AND md.id = cm.module AND m.id = 185 LIMIT 100 4) 680 SELECT * FROM loom_context WHERE contextlevel = '10' LIMIT 1 5) 364 SELECT id, assignmenttype, name FROM loom_assignment WHERE id = '642' LIMIT 100 i'm working on a patch to reduce the {course_modules} queries by lumping some queries together..
        Hide
        Aparup Banerjee added a comment -

        ok , i just dreamt up this patch. Can anyone test and see if theres anything wrong with it? seems fine on my end.

        Show
        Aparup Banerjee added a comment - ok , i just dreamt up this patch. Can anyone test and see if theres anything wrong with it? seems fine on my end.
        Hide
        Aparup Banerjee added a comment -

        no, sorry thats screwing up pagination.

        Show
        Aparup Banerjee added a comment - no, sorry thats screwing up pagination.
        Hide
        Aparup Banerjee added a comment -

        ok, just committed a fix into 1.9.9+. saved a lot of re-querying.

        Show
        Aparup Banerjee added a comment - ok, just committed a fix into 1.9.9+. saved a lot of re-querying.
        Hide
        Martin Dougiamas added a comment -

        Did this also get merged to HEAD? or was it not required?

        Show
        Martin Dougiamas added a comment - Did this also get merged to HEAD? or was it not required?
        Hide
        Aparup Banerjee added a comment -

        a merge was done according to memory, its not showing up here, looking for the commit.

        Show
        Aparup Banerjee added a comment - a merge was done according to memory, its not showing up here, looking for the commit.
        Hide
        Aparup Banerjee added a comment -

        moved merge tag for 19 stable.
        (strange that my last attempt (with co-pilot sam) didn't go through)

        Show
        Aparup Banerjee added a comment - moved merge tag for 19 stable. (strange that my last attempt (with co-pilot sam) didn't go through)
        Hide
        Aparup Banerjee added a comment -

        ps: the 'merge' was to remove a redundant line for 20 stable.

        Show
        Aparup Banerjee added a comment - ps: the 'merge' was to remove a redundant line for 20 stable.
        Hide
        Aparup Banerjee added a comment -

        Just for the record,
        i was investigating what had happened with my merge and found out that i actually never did a merge. ( i was thinking of the merge i did in MDL-24469)
        after checking, the fix had to go through to HEAD.

        The merge is done now and I have committed the fix against HEAD. ( merge tag for 1.9 has already been moved)

        All should be good now.

        Show
        Aparup Banerjee added a comment - Just for the record, i was investigating what had happened with my merge and found out that i actually never did a merge. ( i was thinking of the merge i did in MDL-24469 ) after checking, the fix had to go through to HEAD. The merge is done now and I have committed the fix against HEAD. ( merge tag for 1.9 has already been moved) All should be good now.

          People

          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: