Moodle
  1. Moodle
  2. MDL-9617

Performance issues primarily administrator

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 1.8
    • Fix Version/s: 1.8.1, 1.9
    • Component/s: Unknown
    • Labels:
      None
    • Environment:
      Tested on
      Mac OS 10.4: MySQL 4.1.18, Apache 1.3, PHP 4.4.4
      Linux RHE4: MySQL 4.1.20, Apache 2.0 PHP 4.3.9
      same issues in both setups.
    • Affected Branches:
      MOODLE_18_STABLE
    • Fixed Branches:
      MOODLE_18_STABLE, MOODLE_19_STABLE
    • Rank:
      24574

      Description

      Page load times at 16-120 (although hovering around 16-20) seconds for the admin, other users seem to hover around less than 1 up to 3 seconds.

      Profiling for the front page (percentages are rough)
      The left column content on the frontpage tends to take 66% of the load time for the admin user. Of this 66%, 14% is spent in blocks_have_content() mostly spent on one instance of site_main_menu, the remaining 86% (of the 66%) is spent in blocks_print_group().

      Call to @session_start() in setup.php takes 33% of the load time. I have seen the admin session be over 32 megs, but these are typically 18MB!!!! I think the roles system for the admin needs to be cleaned up considerably.

      The testing scenario I have is 12,850 courses, 15650 users, and 144687 role_assignments. This is 4 semesters of courses, students and the corresponding enrollments.

      Not seeing any slow queries via MySQL other than this one:

      SELECT c.* FROM mdl_course c ORDER BY visible DESC, sortorder ASC;

      Which, as far as I can tell can't be optimized via db adjustments it uses a file sort, if not all of the columns are necessary then it should be restricted to just those needed so that an in memory sort could be performed. However, I really don't understand why the calendar block would need to perform such a query. This is called via calendar/lib.php in calendar_get_default_courses(). However, I don't believe this db query is causing the majority of the performance issues we are experiencing.

        Activity

        Hide
        Jeff Graham added a comment -

        I will not have access to this information after Monday so please get back to me ASAP if you need more information.

        Show
        Jeff Graham added a comment - I will not have access to this information after Monday so please get back to me ASAP if you need more information.
        Hide
        Martín Langhoff added a comment -

        Working on this - I'll publish some early experimental patches monday/tuesday to http://git.catalyst.net.nz/gitweb?p=moodle-r2.git;a=shortlog;h=mdl18-local

        That branch already has some patches to auth/db and enrol/db that make them work with my test case (43k users, 3K courses, 140k enrolments). The changes there might be a bit disruptive specially around accesslib, but my priority on that branch is to make things work with a constant number of db queries regardless of number of categories, courses, users.

        Show
        Martín Langhoff added a comment - Working on this - I'll publish some early experimental patches monday/tuesday to http://git.catalyst.net.nz/gitweb?p=moodle-r2.git;a=shortlog;h=mdl18-local That branch already has some patches to auth/db and enrol/db that make them work with my test case (43k users, 3K courses, 140k enrolments). The changes there might be a bit disruptive specially around accesslib, but my priority on that branch is to make things work with a constant number of db queries regardless of number of categories, courses, users.
        Hide
        Martín Langhoff added a comment -

        Jeff - interesting numbers, specually about the session. Can you enable PERF_TO_LOG and tell us what number of dbquereis you get?

        Show
        Martín Langhoff added a comment - Jeff - interesting numbers, specually about the session. Can you enable PERF_TO_LOG and tell us what number of dbquereis you get?
        Hide
        Martin Dougiamas added a comment -

        Just a suggestion: the calendar block is probably trying to show all events from all courses for the admin. If you remove that one block is everything much better?

        Show
        Martin Dougiamas added a comment - Just a suggestion: the calendar block is probably trying to show all events from all courses for the admin. If you remove that one block is everything much better?
        Hide
        Hans added a comment -

        I removed the block calendar mounth and also calendar upcoming.
        It didn't had any effect on the login time. About 26 seconds (stopwatch)

        Show
        Hans added a comment - I removed the block calendar mounth and also calendar upcoming. It didn't had any effect on the login time. About 26 seconds (stopwatch)
        Hide
        Jeff Graham added a comment -

        Hi All some more data here.

        Removing the calendar block has no effect. Also just for reference calendar_adminseesall is unset.

        Indirectly the admin_tree block is the problem, via a long chain of includes/calls that ends up in a call to calendar_get_default_courses().

        If you don't care about the calling chain skip this next one: block_admin_tree -> admin_get_root() -> include_once(admin/settings/appearance.php) -> require_once(/calendar/lib.php) -> calendar_session_vars() -> calendar_get_default_courses()

        So it does turn out that this is directly related to the slow query I mentioned in the initial report, although the query typically doesn't show up in the slow queries log so this is largely a PHP issue still.

        After reviewing calendar_get_default_courses() I really don't understand what this is used for. It either returns; A single valued array, an array of courses, or an array keyed by course id with role assignments for the data. Seems rather odd to me. Based on the first return value of array($SESSION->cal_course_referer => 1); I would assume that the $allcourses if could be changed to "return $allcourses = get_my_courses($USER->id, 'visible DESC, sortorder ASC', '*', true)"

        Furthermore the get_my_courses() call should be cleaned up. It seems the last parameter should reflect the setting of $CFG->calendar_adminseesall so that the function is more like "return $allcourses = get_my_courses($USER->id, 'visible DESC, sortorder ASC', 'id, 1', $CFG->adminseesall);" not sure if the "id, 1" is cross-db okay, but that should help to resolve the slow query issues.

        Dropping that last' $allcourses' if block in calendar_get_default_courses() and changing to "return get_my_courses($USER->id, 'visible DESC, sortorder ASC', 'id, 1', $CFG->adminseesall);" seems to remove the majority of the loading issues.

        However the load times now seem to hover around 3 seconds of this 85-90% seems to be spent on the single call to @session_start()

        Show
        Jeff Graham added a comment - Hi All some more data here. Removing the calendar block has no effect. Also just for reference calendar_adminseesall is unset. Indirectly the admin_tree block is the problem, via a long chain of includes/calls that ends up in a call to calendar_get_default_courses(). If you don't care about the calling chain skip this next one: block_admin_tree -> admin_get_root() -> include_once(admin/settings/appearance.php) -> require_once(/calendar/lib.php) -> calendar_session_vars() -> calendar_get_default_courses() So it does turn out that this is directly related to the slow query I mentioned in the initial report, although the query typically doesn't show up in the slow queries log so this is largely a PHP issue still. After reviewing calendar_get_default_courses() I really don't understand what this is used for. It either returns; A single valued array, an array of courses, or an array keyed by course id with role assignments for the data. Seems rather odd to me. Based on the first return value of array($SESSION->cal_course_referer => 1); I would assume that the $allcourses if could be changed to "return $allcourses = get_my_courses($USER->id, 'visible DESC, sortorder ASC', '*', true)" Furthermore the get_my_courses() call should be cleaned up. It seems the last parameter should reflect the setting of $CFG->calendar_adminseesall so that the function is more like "return $allcourses = get_my_courses($USER->id, 'visible DESC, sortorder ASC', 'id, 1', $CFG->adminseesall);" not sure if the "id, 1" is cross-db okay, but that should help to resolve the slow query issues. Dropping that last' $allcourses' if block in calendar_get_default_courses() and changing to "return get_my_courses($USER->id, 'visible DESC, sortorder ASC', 'id, 1', $CFG->adminseesall);" seems to remove the majority of the loading issues. However the load times now seem to hover around 3 seconds of this 85-90% seems to be spent on the single call to @session_start()
        Hide
        Jeff Graham added a comment -

        After a little testing/reworking the last line should be the following;
        <pre>
        // find all course this student can view
        if (isset($CFG->adminseesall))

        { return get_my_courses($USER->id, 'visible DESC', 'id, visible', $CFG->adminseesall); }

        else

        { return get_my_courses($USER->id, 'visible DESC', 'id, visible', false); }

        </pre>

        Not sure if the sort is truly necessary, but get_my_courses() bombs out on an empty sort field. Limiting the returned fields not only reduces the query time, but also reduces the session size which is now about 1MB for the admin user now.

        This above patch results in all users load times being very snappy, at least by comparison. For the admin user the initial login is about 21 seconds or so, but subsequent page loads are under 1 second. Sorry about not posting a diff... anoncvs is still blocked so that makes things difficult.

        Show
        Jeff Graham added a comment - After a little testing/reworking the last line should be the following; <pre> // find all course this student can view if (isset($CFG->adminseesall)) { return get_my_courses($USER->id, 'visible DESC', 'id, visible', $CFG->adminseesall); } else { return get_my_courses($USER->id, 'visible DESC', 'id, visible', false); } </pre> Not sure if the sort is truly necessary, but get_my_courses() bombs out on an empty sort field. Limiting the returned fields not only reduces the query time, but also reduces the session size which is now about 1MB for the admin user now. This above patch results in all users load times being very snappy, at least by comparison. For the admin user the initial login is about 21 seconds or so, but subsequent page loads are under 1 second. Sorry about not posting a diff... anoncvs is still blocked so that makes things difficult.
        Hide
        Jeff Graham added a comment -

        attached diff to explain what I've done.

        Please comment on the appropriateness of this.

        Show
        Jeff Graham added a comment - attached diff to explain what I've done. Please comment on the appropriateness of this.
        Hide
        Martin Dougiamas added a comment -

        Great work, Jeff, thanks!

        Yu, can you review this patch and check it in to 1.8 and HEAD?

        Show
        Martin Dougiamas added a comment - Great work, Jeff, thanks! Yu, can you review this patch and check it in to 1.8 and HEAD?
        Hide
        Martin Dougiamas added a comment -

        Also look into making get_my_courses() work with an empty sort field (since we don't need sorted courses here, I don't think)

        Show
        Martin Dougiamas added a comment - Also look into making get_my_courses() work with an empty sort field (since we don't need sorted courses here, I don't think)
        Hide
        Matt Clarkson added a comment -

        I have also been working on the performance issues in the calendar and have made some optimisations that go beyond the login and speed up all pages displaying the calendar block.

        I found that with a database containing 2500 courses the login process was resulting in about 15K queries and generating the home page (and others) was taking around 5K queries.

        The patches located at the link below result a constant 150 queries for both login and home page generation with my 2500 course database.

        http://git.catalyst.net.nz/gitweb?p=moodle-r2.git;a=shortlog;h=mdl18-calendaropt3

        The main difference between this patch and Jeff's is that I have optimised the calendar_set_filters() function to remove a couple of queries sitting inside a loop.

        Show
        Matt Clarkson added a comment - I have also been working on the performance issues in the calendar and have made some optimisations that go beyond the login and speed up all pages displaying the calendar block. I found that with a database containing 2500 courses the login process was resulting in about 15K queries and generating the home page (and others) was taking around 5K queries. The patches located at the link below result a constant 150 queries for both login and home page generation with my 2500 course database. http://git.catalyst.net.nz/gitweb?p=moodle-r2.git;a=shortlog;h=mdl18-calendaropt3 The main difference between this patch and Jeff's is that I have optimised the calendar_set_filters() function to remove a couple of queries sitting inside a loop.
        Hide
        Wen Hao Chuang added a comment -

        just curious, did Jeff or Matt's patches got into the 18_stable branch yet? As the sourceforge anonymous CVS is still down , if the fix did get into the branch where could I download the most recent 1.8+ codes? Thanks!

        Show
        Wen Hao Chuang added a comment - just curious, did Jeff or Matt's patches got into the 18_stable branch yet? As the sourceforge anonymous CVS is still down , if the fix did get into the branch where could I download the most recent 1.8+ codes? Thanks!
        Hide
        Yu Zhang added a comment -

        Hi, this code didn't quite work for me because it looks for id, visible. And that will be cached by get_my_courses(). Later, when get_my_courses is called, only id, visible is returned and that leads to blank course name for students. I changed this bit and also made get_my_courses() to only cache if all fields are requested. Since this is called later anyway I it's ok to cache it with all fields. Thanks for the patch! Cheers, Yu.

        Show
        Yu Zhang added a comment - Hi, this code didn't quite work for me because it looks for id, visible. And that will be cached by get_my_courses(). Later, when get_my_courses is called, only id, visible is returned and that leads to blank course name for students. I changed this bit and also made get_my_courses() to only cache if all fields are requested. Since this is called later anyway I it's ok to cache it with all fields. Thanks for the patch! Cheers, Yu.
        Hide
        Martín Langhoff added a comment -

        Having a skype conversation with Yu - he never read our patches, which fix a whole lot of other perf problems in get_my_courses().

        Show
        Martín Langhoff added a comment - Having a skype conversation with Yu - he never read our patches, which fix a whole lot of other perf problems in get_my_courses().
        Hide
        Dan Poltawski added a comment -

        For info, i'm fairly sure that calendar/lib.php is only called within admin/settings/appearance.php for the constants CALENDAR_TF_12 and CALENDAR_TF_24 (cos it was my patch which did it ). And it doesn't require any other calendar session variables (so could be removed so that it isn't setup for every admin logging in with an admin block..)

        Show
        Dan Poltawski added a comment - For info, i'm fairly sure that calendar/lib.php is only called within admin/settings/appearance.php for the constants CALENDAR_TF_12 and CALENDAR_TF_24 (cos it was my patch which did it ). And it doesn't require any other calendar session variables (so could be removed so that it isn't setup for every admin logging in with an admin block..)
        Hide
        Martin Dougiamas added a comment -

        ML thanks for the link. Those links to your gitweb are a bit confusing though because the page lists all sorts of things ... what bit is relevant here?

        Others, can you test 1.8 STABLE and let us know (here) if you see improvements?

        Show
        Martin Dougiamas added a comment - ML thanks for the link. Those links to your gitweb are a bit confusing though because the page lists all sorts of things ... what bit is relevant here? Others, can you test 1.8 STABLE and let us know (here) if you see improvements?
        Hide
        Hans added a comment - - edited

        Maybe not the right place to post but my test results with
        Moodle 1.8 latest 2007/05/04 and..

        version calendar lib.php login time (sec): ............... admin-- student

        lib.php,v 1.175 2007/05/04 05:25:49 toyomoyo ......... 22.10-- 6.40
        lib.php,v 1.174 2007/04/27 06:30:21 moodler ............ 16.30-- 6.10
        lib.php,v 1.164.2.10 2007/04/27 06:28:35 moodler .... 15.70-- 6.10

        Apache/2.2.3 (Ubuntu 7.04) PHP/5.2.1 MySql 5.0.38
        mdl_categories = 2200 records
        mdl_courses=3800 records

        Show
        Hans added a comment - - edited Maybe not the right place to post but my test results with Moodle 1.8 latest 2007/05/04 and.. version calendar lib.php login time (sec): ............... admin-- student lib.php,v 1.175 2007/05/04 05:25:49 toyomoyo ......... 22.10-- 6.40 lib.php,v 1.174 2007/04/27 06:30:21 moodler ............ 16.30-- 6.10 lib.php,v 1.164.2.10 2007/04/27 06:28:35 moodler .... 15.70-- 6.10 Apache/2.2.3 (Ubuntu 7.04) PHP/5.2.1 MySql 5.0.38 mdl_categories = 2200 records mdl_courses=3800 records
        Hide
        Hans added a comment -

        Thanks to everyone
        Login as admin now about 4 sec.

        After a fresh install 1.8 , 1.8 latest, copy mysql 1.6.3 database (production) and upgrading to 1.8 all went fine using lib.php,v 1.175 (2007/05/04 05:25:49)

        Apache/2.2.3 (Ubuntu 7.04) PHP/5.2.1 MySql 5.0.38
        mdl_categories = 2200 records
        mdl_courses=3800 records

        Show
        Hans added a comment - Thanks to everyone Login as admin now about 4 sec. After a fresh install 1.8 , 1.8 latest, copy mysql 1.6.3 database (production) and upgrading to 1.8 all went fine using lib.php,v 1.175 (2007/05/04 05:25:49) Apache/2.2.3 (Ubuntu 7.04) PHP/5.2.1 MySql 5.0.38 mdl_categories = 2200 records mdl_courses=3800 records
        Hide
        Martín Langhoff added a comment -

        Merged in our Matt's patches into 18_STABLE and HEAD - sorry about the delay.

        Can you guys re-test with latest 18_STABLE and let us know?

        Show
        Martín Langhoff added a comment - Merged in our Matt's patches into 18_STABLE and HEAD - sorry about the delay. Can you guys re-test with latest 18_STABLE and let us know?
        Hide
        Hans added a comment -

        Switching between lib.php,v 1.175 (2007/05/04) and lib.php,v 1.179 2007/05/06
        After 20 times login each (with stopwatch)
        login as admin is a fraction (0.2 sec) faster with latest version.
        Logintime 2 sec + bulding frames frontpage 2.7 sec = total 4.7 sec

        Login as student I couldnt see any difference. ( about 5.8 sec)
        Using both scripts its remarkable that login as admin is 25% faster then login as student.

        Show
        Hans added a comment - Switching between lib.php,v 1.175 (2007/05/04) and lib.php,v 1.179 2007/05/06 After 20 times login each (with stopwatch) login as admin is a fraction (0.2 sec) faster with latest version. Logintime 2 sec + bulding frames frontpage 2.7 sec = total 4.7 sec Login as student I couldnt see any difference. ( about 5.8 sec) Using both scripts its remarkable that login as admin is 25% faster then login as student.
        Hide
        Martin Dougiamas added a comment -

        Martin L, a gentle reminder to include bug number (MDL-9617) in the CVS comment so the patches get added to the bug.

        Show
        Martin Dougiamas added a comment - Martin L, a gentle reminder to include bug number ( MDL-9617 ) in the CVS comment so the patches get added to the bug.
        Hide
        Martín Langhoff added a comment -

        Hi Hans - the stopwatch approach doesn't give us much useful info. I'm interested in what PERF_TO_LOG tells you, number of dbqueries specifically.

        Show
        Martín Langhoff added a comment - Hi Hans - the stopwatch approach doesn't give us much useful info. I'm interested in what PERF_TO_LOG tells you, number of dbqueries specifically.
        Hide
        Martín Langhoff added a comment -

        MartinD - I did put the bug numbers in the commits that were clearly related to this. For some reason Jira didn't catch them

        Show
        Martín Langhoff added a comment - MartinD - I did put the bug numbers in the commits that were clearly related to this. For some reason Jira didn't catch them
        Hide
        Hans added a comment -

        I'm sorry how can I enable perf_to_log ??
        If you mean mysql log files you can download them here:
        http://elo.imcvo.nl/web/mysql_log_files.tar.gz

        Show
        Hans added a comment - I'm sorry how can I enable perf_to_log ?? If you mean mysql log files you can download them here: http://elo.imcvo.nl/web/mysql_log_files.tar.gz
        Hide
        Martín Langhoff added a comment -

        Look in your config-dist.php for the settings, and copy them to your config.php. With that, moodle will be recording good profiling data into apache's error log.

        Show
        Martín Langhoff added a comment - Look in your config-dist.php for the settings, and copy them to your config.php. With that, moodle will be recording good profiling data into apache's error log.
        Hide
        Wen Hao Chuang added a comment -

        OK we tested the most recent build lib.php ($Id: lib.php,v 1.164.2.16 2007/05/06 23:41:37 mattc-catalyst Exp), here is the result (enabled the PERF_TO_LOG):

        [Mon May 07 12:00:51 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/course/category.php?id=33 time: 2.299621s includecount: 40 dbqueries: 1286 ticks: 230 user: 137 sys: 6 cuser: 0 csys: 0 serverload: 0.36 rcache: 0/0 , referer: http://ilearnstage.sfsu.edu/pleasework/
        [Mon May 07 12:00:56 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/course/category.php?id=4 time: 0.352387s includecount: 45 dbqueries: 89 ticks: 35 user: 31 sys: 2 cuser: 0 csys: 0 serverload: 0.33 rcache: 0/0 , referer: http://ilearnstage.sfsu.edu/pleasework/
        [Mon May 07 12:07:26 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/ time: 0.74062s includecount: 106 dbqueries: 85 logwrites: 1 ticks: 74 user: 64 sys: 9 cuser: 0 csys: 1 serverload: 0.02 rcache: 0/0
        [Mon May 07 12:07:29 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/login/index.php time: 0.34507s includecount: 43 dbqueries: 7 ticks: 35 user: 33 sys: 0 cuser: 0 csys: 0 serverload: 0.02 rcache: 0/0 , referer: http://ilearnstage.sfsu.edu/pleasework/
        [Mon May 07 12:07:33 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/ time: 0.72981s includecount: 103 dbqueries: 83 logwrites: 1 ticks: 73 user: 65 sys: 7 cuser: 0 csys: 0 serverload: 0.02 rcache: 0/0 , referer: http://ilearnstage.sfsu.edu/pleasework/login/index.php
        [Mon May 07 12:07:53 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/login/index.php time: 0.34859s includecount: 42 dbqueries: 7 ticks: 34 user: 33 sys: 0 cuser: 0 csys: 0 serverload: 0.01 rcache: 0/0
        [Mon May 07 12:07:58 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/ time: 0.730083s includecount: 103 dbqueries: 83 logwrites: 1 ticks: 73 user: 63 sys: 8 cuser: 0 csys: 1 serverload: 0.01 rcache: 0/0 , referer: http://ilearnstage.sfsu.edu/pleasework/login/index.php

        The new patch seems to work very well, here is our setting:
        Apache/2.2.3 (RH Enterprise) PHP/5.1.4 MySql 5.0.22
        mdl_course_categories = 34 records
        mdl_courses=46016 records
        mdl_user=77925 records

        Show
        Wen Hao Chuang added a comment - OK we tested the most recent build lib.php ($Id: lib.php,v 1.164.2.16 2007/05/06 23:41:37 mattc-catalyst Exp), here is the result (enabled the PERF_TO_LOG): [Mon May 07 12:00:51 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/course/category.php?id=33 time: 2.299621s includecount: 40 dbqueries: 1286 ticks: 230 user: 137 sys: 6 cuser: 0 csys: 0 serverload: 0.36 rcache: 0/0 , referer: http://ilearnstage.sfsu.edu/pleasework/ [Mon May 07 12:00:56 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/course/category.php?id=4 time: 0.352387s includecount: 45 dbqueries: 89 ticks: 35 user: 31 sys: 2 cuser: 0 csys: 0 serverload: 0.33 rcache: 0/0 , referer: http://ilearnstage.sfsu.edu/pleasework/ [Mon May 07 12:07:26 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/ time: 0.74062s includecount: 106 dbqueries: 85 logwrites: 1 ticks: 74 user: 64 sys: 9 cuser: 0 csys: 1 serverload: 0.02 rcache: 0/0 [Mon May 07 12:07:29 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/login/index.php time: 0.34507s includecount: 43 dbqueries: 7 ticks: 35 user: 33 sys: 0 cuser: 0 csys: 0 serverload: 0.02 rcache: 0/0 , referer: http://ilearnstage.sfsu.edu/pleasework/ [Mon May 07 12:07:33 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/ time: 0.72981s includecount: 103 dbqueries: 83 logwrites: 1 ticks: 73 user: 65 sys: 7 cuser: 0 csys: 0 serverload: 0.02 rcache: 0/0 , referer: http://ilearnstage.sfsu.edu/pleasework/login/index.php [Mon May 07 12:07:53 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/login/index.php time: 0.34859s includecount: 42 dbqueries: 7 ticks: 34 user: 33 sys: 0 cuser: 0 csys: 0 serverload: 0.01 rcache: 0/0 [Mon May 07 12:07:58 2007] [error] [client xxx.xx.xx.xx] PERF: /pleasework/ time: 0.730083s includecount: 103 dbqueries: 83 logwrites: 1 ticks: 73 user: 63 sys: 8 cuser: 0 csys: 1 serverload: 0.01 rcache: 0/0 , referer: http://ilearnstage.sfsu.edu/pleasework/login/index.php The new patch seems to work very well, here is our setting: Apache/2.2.3 (RH Enterprise) PHP/5.1.4 MySql 5.0.22 mdl_course_categories = 34 records mdl_courses=46016 records mdl_user=77925 records
        Hide
        Hans added a comment -

        Test with 3 scripts.
        firstlogin as admin second login as student.

        lib.php,v 1.164.2.16 2007/05/06 23:41:37 mattc-catalyst Exp
        [Mon May 07 21:48:13 2007] [error] [client 172.16.0.150] PERF: / time: 8.776136s memory_total: 13550124B (12.9MB) memory_growth: 13273524B (12.7MB) includecount: 104 dbqueries: 3837 serverload: 1.05 rcache: 0/0
        [Mon May 07 21:48:29 2007] [error] [client 172.16.0.150] PERF: / time: 5.170025s memory_total: 13648708B (13MB) memory_growth: 13371340B (12.8MB) includecount: 118 dbqueries: 2144 logwrites: 1 serverload: 1.22 rcache: 0/0 , referer: http://elo.imcvo.nl/
        [Mon May 07 21:48:35 2007] [error] [client 172.16.0.150] PERF: / time: 3.436985s memory_total: 13429068B (12.8MB) memory_growth: 13152056B (12.5MB) includecount: 99 dbqueries: 3834 serverload: 1.35 rcache: 0/0 , referer: http://elo.imcvo.nl/
        [Mon May 07 21:48:52 2007] [error] [client 172.16.0.150] PERF: / time: 3.349699s memory_total: 13677868B (13MB) memory_growth: 13400464B (12.8MB) includecount: 99 dbqueries: 3810 logwrites: 1 serverload: 1.21 rcache: 0/0 , referer: http://elo.imcvo.nl/

        lib.php,v 1.179 2007/05/06 05:32:40 martinlanghoff Exp $
        [Mon May 07 21:38:40 2007] [error] [client 172.16.0.150] PERF: / time: 8.645043s memory_total: 13551028B (12.9MB) memory_growth: 13274428B (12.7MB) includecount: 104 dbqueries: 3837 serverload: 0.72 rcache: 0/0
        [Mon May 07 21:38:57 2007] [error] [client 172.16.0.150] PERF: / time: 4.661826s memory_total: 13647688B (13MB) memory_growth: 13370320B (12.8MB) includecount: 118 dbqueries: 2144 logwrites: 1 serverload: 0.64 rcache: 0/0 , referer: http://elo.imcvo.nl/
        [Mon May 07 21:39:06 2007] [error] [client 172.16.0.150] PERF: / time: 3.348734s memory_total: 13429664B (12.8MB) memory_growth: 13152652B (12.5MB) includecount: 99 dbqueries: 3834 serverload: 0.78 rcache: 0/0 , referer: http://elo.imcvo.nl/
        [Mon May 07 21:39:23 2007] [error] [client 172.16.0.150] PERF: / time: 3.333891s memory_total: 13676704B (13MB) memory_growth: 13399300B (12.8MB) includecount: 99 dbqueries: 3810 logwrites: 1 serverload: 0.93 rcache: 0/0 , referer: http://elo.imcvo.nl/
        [Mon May 07 21:39:28 2007] [error] [client 172.16.0.150] PERF: / time: 3.347086s memory_total: 13427948B (12.8MB) memory_growth: 13150900B (12.5MB) includecount: 99 dbqueries: 3834 serverload: 1.01 rcache: 0/0 , referer: http://elo.imcvo.nl/

        lib.php,v 1.175 2007/05/04 05:25:49 toyomoyo Exp $
        [Mon May 07 21:26:02 2007] [error] [client 172.16.0.150] PERF: / time: 8.841707s memory_total: 13547764B (12.9MB) memory_growth: 13271200B (12.7MB) includecount: 104 dbqueries: 3838 serverload: 0.77 rcache: 0/0
        [Mon May 07 21:26:11 2007] [error] [client 172.16.0.150] PERF: / time: 5.220224s memory_total: 13675428B (13MB) memory_growth: 13398060B (12.8MB) includecount: 118 dbqueries: 2183 logwrites: 1 serverload: 0.73 rcache: 0/0 , referer: http://elo.imcvo.nl/
        [Mon May 07 21:30:14 2007] [error] [client 172.16.0.150] PERF: / time: 3.264151s memory_total: 13548800B (12.9MB) memory_growth: 13271788B (12.7MB) includecount: 104 dbqueries: 3838 ticks: 326 user: 252 sys: 14 cuser: 0 csys: 0 serverload: 0.17 rcache: 0/0 , referer: http://elo.imcvo.nl/
        [Mon May 07 21:30:36 2007] [error] [client 172.16.0.150] PERF: / time: 3.918087s memory_total: 14088076B (13.4MB) memory_growth: 13810672B (13.2MB) includecount: 99 dbqueries: 4484 logwrites: 1 ticks: 392 user: 278 sys: 12 cuser: 0 csys: 0 serverload: 0.68 rcache: 0/0 , referer: http://elo.imcvo.nl/
        [Mon May 07 21:32:08 2007] [error] [client 172.16.0.150] PERF: / time: 3.416897s memory_total: 13549380B (12.9MB) memory_growth: 13272152B (12.7MB) includecount: 104 dbqueries: 3838 ticks: 341 user: 260 sys: 8 cuser: 0 csys: 0 serverload: 0.23 rcache: 0/0 , referer: http://elo.imcvo.nl/

        Apache/2.2.3 (Ubuntu 7.04) PHP/5.2.1 MySql 5.0.38
        mdl_categories = 2200 records
        mdl_courses=3800 records

        If you need some more just let me know.
        Which script is best for me?

        Show
        Hans added a comment - Test with 3 scripts. firstlogin as admin second login as student. lib.php,v 1.164.2.16 2007/05/06 23:41:37 mattc-catalyst Exp [Mon May 07 21:48:13 2007] [error] [client 172.16.0.150] PERF: / time: 8.776136s memory_total: 13550124B (12.9MB) memory_growth: 13273524B (12.7MB) includecount: 104 dbqueries: 3837 serverload: 1.05 rcache: 0/0 [Mon May 07 21:48:29 2007] [error] [client 172.16.0.150] PERF: / time: 5.170025s memory_total: 13648708B (13MB) memory_growth: 13371340B (12.8MB) includecount: 118 dbqueries: 2144 logwrites: 1 serverload: 1.22 rcache: 0/0 , referer: http://elo.imcvo.nl/ [Mon May 07 21:48:35 2007] [error] [client 172.16.0.150] PERF: / time: 3.436985s memory_total: 13429068B (12.8MB) memory_growth: 13152056B (12.5MB) includecount: 99 dbqueries: 3834 serverload: 1.35 rcache: 0/0 , referer: http://elo.imcvo.nl/ [Mon May 07 21:48:52 2007] [error] [client 172.16.0.150] PERF: / time: 3.349699s memory_total: 13677868B (13MB) memory_growth: 13400464B (12.8MB) includecount: 99 dbqueries: 3810 logwrites: 1 serverload: 1.21 rcache: 0/0 , referer: http://elo.imcvo.nl/ lib.php,v 1.179 2007/05/06 05:32:40 martinlanghoff Exp $ [Mon May 07 21:38:40 2007] [error] [client 172.16.0.150] PERF: / time: 8.645043s memory_total: 13551028B (12.9MB) memory_growth: 13274428B (12.7MB) includecount: 104 dbqueries: 3837 serverload: 0.72 rcache: 0/0 [Mon May 07 21:38:57 2007] [error] [client 172.16.0.150] PERF: / time: 4.661826s memory_total: 13647688B (13MB) memory_growth: 13370320B (12.8MB) includecount: 118 dbqueries: 2144 logwrites: 1 serverload: 0.64 rcache: 0/0 , referer: http://elo.imcvo.nl/ [Mon May 07 21:39:06 2007] [error] [client 172.16.0.150] PERF: / time: 3.348734s memory_total: 13429664B (12.8MB) memory_growth: 13152652B (12.5MB) includecount: 99 dbqueries: 3834 serverload: 0.78 rcache: 0/0 , referer: http://elo.imcvo.nl/ [Mon May 07 21:39:23 2007] [error] [client 172.16.0.150] PERF: / time: 3.333891s memory_total: 13676704B (13MB) memory_growth: 13399300B (12.8MB) includecount: 99 dbqueries: 3810 logwrites: 1 serverload: 0.93 rcache: 0/0 , referer: http://elo.imcvo.nl/ [Mon May 07 21:39:28 2007] [error] [client 172.16.0.150] PERF: / time: 3.347086s memory_total: 13427948B (12.8MB) memory_growth: 13150900B (12.5MB) includecount: 99 dbqueries: 3834 serverload: 1.01 rcache: 0/0 , referer: http://elo.imcvo.nl/ lib.php,v 1.175 2007/05/04 05:25:49 toyomoyo Exp $ [Mon May 07 21:26:02 2007] [error] [client 172.16.0.150] PERF: / time: 8.841707s memory_total: 13547764B (12.9MB) memory_growth: 13271200B (12.7MB) includecount: 104 dbqueries: 3838 serverload: 0.77 rcache: 0/0 [Mon May 07 21:26:11 2007] [error] [client 172.16.0.150] PERF: / time: 5.220224s memory_total: 13675428B (13MB) memory_growth: 13398060B (12.8MB) includecount: 118 dbqueries: 2183 logwrites: 1 serverload: 0.73 rcache: 0/0 , referer: http://elo.imcvo.nl/ [Mon May 07 21:30:14 2007] [error] [client 172.16.0.150] PERF: / time: 3.264151s memory_total: 13548800B (12.9MB) memory_growth: 13271788B (12.7MB) includecount: 104 dbqueries: 3838 ticks: 326 user: 252 sys: 14 cuser: 0 csys: 0 serverload: 0.17 rcache: 0/0 , referer: http://elo.imcvo.nl/ [Mon May 07 21:30:36 2007] [error] [client 172.16.0.150] PERF: / time: 3.918087s memory_total: 14088076B (13.4MB) memory_growth: 13810672B (13.2MB) includecount: 99 dbqueries: 4484 logwrites: 1 ticks: 392 user: 278 sys: 12 cuser: 0 csys: 0 serverload: 0.68 rcache: 0/0 , referer: http://elo.imcvo.nl/ [Mon May 07 21:32:08 2007] [error] [client 172.16.0.150] PERF: / time: 3.416897s memory_total: 13549380B (12.9MB) memory_growth: 13272152B (12.7MB) includecount: 104 dbqueries: 3838 ticks: 341 user: 260 sys: 8 cuser: 0 csys: 0 serverload: 0.23 rcache: 0/0 , referer: http://elo.imcvo.nl/ Apache/2.2.3 (Ubuntu 7.04) PHP/5.2.1 MySql 5.0.38 mdl_categories = 2200 records mdl_courses=3800 records If you need some more just let me know. Which script is best for me?
        Hide
        Wen Hao Chuang added a comment -

        By the way with our current number (mdl_courses=46016 records and mdl_user=77925 records) there are other performance issues after we did the most recent patch:

        [login as a admin]:
        1. When clicked on "Search courses ..." link in the Course categories, the course/index.php took 59.742003 secs to complete, Included 67 files DB queries 44472 ticks: 5975 user: 1666 sys: 137 cuser: 0 csys: 0 Load average: 0.75 Record cache hit/miss ratio : 0/0
        2. When clicked on the "All courses ..." link, the course/index.php took 66.997843 secs Included 67 files DB queries 44472 ticks: 6700 user: 1957 sys: 184 cuser: 0 csys: 0 Load average: 0.99 Record cache hit/miss ratio : 0/0

        Should I create another ticket for this issue or should we continue to document these issues in this ticket (in that case should we reopen this ticket then? As it is not really resolved with all performance issues). Thanks!

        Show
        Wen Hao Chuang added a comment - By the way with our current number (mdl_courses=46016 records and mdl_user=77925 records) there are other performance issues after we did the most recent patch: [login as a admin] : 1. When clicked on "Search courses ..." link in the Course categories, the course/index.php took 59.742003 secs to complete, Included 67 files DB queries 44472 ticks: 5975 user: 1666 sys: 137 cuser: 0 csys: 0 Load average: 0.75 Record cache hit/miss ratio : 0/0 2. When clicked on the "All courses ..." link, the course/index.php took 66.997843 secs Included 67 files DB queries 44472 ticks: 6700 user: 1957 sys: 184 cuser: 0 csys: 0 Load average: 0.99 Record cache hit/miss ratio : 0/0 Should I create another ticket for this issue or should we continue to document these issues in this ticket (in that case should we reopen this ticket then? As it is not really resolved with all performance issues). Thanks!
        Hide
        Wen Hao Chuang added a comment -

        second test:

        [login as a admin]:
        1. When clicked on "Search courses ..." link in the Course categories, the course/index.php took 0.291206 secs Included 39 files DB queries 113 ticks: 29 user: 27 sys: 2 cuser: 0 csys: 0 Load average: 0.00 Record cache hit/miss ratio : 0/0
        2. When clicked on the "All courses ..." link, the course/index.php took 0.295275 secs Included 39 files DB queries 113 ticks: 30 user: 28 sys: 1 cuser: 0 csys: 0 Load average: 0.00 Record cache hit/miss ratio : 0/0
        Maybe it got cached or something, I'm still looking into the reason..

        Show
        Wen Hao Chuang added a comment - second test: [login as a admin] : 1. When clicked on "Search courses ..." link in the Course categories, the course/index.php took 0.291206 secs Included 39 files DB queries 113 ticks: 29 user: 27 sys: 2 cuser: 0 csys: 0 Load average: 0.00 Record cache hit/miss ratio : 0/0 2. When clicked on the "All courses ..." link, the course/index.php took 0.295275 secs Included 39 files DB queries 113 ticks: 30 user: 28 sys: 1 cuser: 0 csys: 0 Load average: 0.00 Record cache hit/miss ratio : 0/0 Maybe it got cached or something, I'm still looking into the reason..

          People

          • Votes:
            6 Vote for this issue
            Watchers:
            8 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: