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

      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.

        Gliffy Diagrams

        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: