Details

    • Type: Sub-task
    • Status: Closed
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 2.3
    • Fix Version/s: 2.4
    • Component/s: Language, Performance
    • Labels:
    • Testing Instructions:
      Hide

      Difficulty: Developer hacking

      1. Browse around the site and ensure strings are loaded
      2. Install a new lang pack and use it, verify new strings are used
      3. Introduce a new string in a the moodle.php lang file
      4. Add use of it in index.php
      5. Increment version.php
      6. Verify that the new string is loaded and displayed
      Show
      Difficulty: Developer hacking Browse around the site and ensure strings are loaded Install a new lang pack and use it, verify new strings are used Introduce a new string in a the moodle.php lang file Add use of it in index.php Increment version.php Verify that the new string is loaded and displayed
    • Affected Branches:
      MOODLE_23_STABLE
    • Fixed Branches:
      MOODLE_24_STABLE
    • Pull Master Branch:
      wip-MDL-34342-m24

      Description

      Define current caching here in detail so we can see if MUC will help.

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

              Hide
              mudrd8mz David Mudrák added a comment -

              Type of data

              • Strings returned by get_string() and other methods.
              • Average length 54 characters, UTF-8 encoded.

              Data structure

              There are two main caches used by the core_string_manager - the on-diskcache and in-memory cache.

              The on-disk cache is used to cache the result of language packs merging. Merging is an operation where official translations are combined with eventual local customizations. Missing strings are filled using the parent language or the English (which is the implicit parent for all languages). At the end of the merge, there is some value defined for each existing string in the given language.

              The in-memory cache is used to cache the strings once they are read from the on-disk cache. If we need a string from the given component, eg. via get_string('foo', 'mod_bar') call, we load all the mod_bar component from the on-disk cache into the in-memory cache and pick the string from it. If another string from the same component is needed, the in-memory cache is hit.

              The in-memory cache is currently implemented as a three-dimensional associative array $cache[$langcode][$component][$stringid].

              When it gets stored

              Both caches are populated on-the-fly when the given string component is accessed for the first time.

              If some string from the component mod_bar is requested and the component mod_bar is not loaded into the memory yet, the core_string_manager reads the whole component from the on-disk cache.

              If the component mod_bar is not found in the on-disk cache yet, all the possible sources of the strings from this component are merged together and stored.

              Where it gets stored

              The core_string_manager (which is a singleton) stores the in-memory cache in its protected $this->cache property.

              The on-disk cache is stored in files in $CFG->langcacheroot which is $CFG->cachedir.'/lang' by default (where $CFG->cachedir itself defaults to $CFG->dataroot.'/cache').

              How it gets read

              In core_string_manager::load_component_strings() that is used by get_string() and friends.

              Does it need locking?

              Yes it does. Especially when the on-disk cache is recreated, two concurrent requests may check for the file existence and either try to use the incomplete data or start overwriting the file again. Petr did recently some tweaks to minimize this race conditions (see d7b44d5e959a66cd3da2e212d0ac1bdcf139d075), some solid solution would be nice for sure.

              How it gets cleared?

              The in-memory cache is a request cache and is cleared automatically at the end of the request.

              The on-disk cache is cleared as a part of the purge_all_caches() call. So it can be cleared manually via the Purge all caches feature, is automatically cleared on core upgrades etc.

              Typical sizes

              The in-memory cache has typically 600KB - 1MB for students and something about 2MB for admins.

              Safeguards in place

              None currently implemented.

              Show
              mudrd8mz David Mudrák added a comment - Type of data Strings returned by get_string() and other methods. Average length 54 characters, UTF-8 encoded. Data structure There are two main caches used by the core_string_manager - the on-diskcache and in-memory cache. The on-disk cache is used to cache the result of language packs merging. Merging is an operation where official translations are combined with eventual local customizations. Missing strings are filled using the parent language or the English (which is the implicit parent for all languages). At the end of the merge, there is some value defined for each existing string in the given language. The in-memory cache is used to cache the strings once they are read from the on-disk cache. If we need a string from the given component, eg. via get_string('foo', 'mod_bar') call, we load all the mod_bar component from the on-disk cache into the in-memory cache and pick the string from it. If another string from the same component is needed, the in-memory cache is hit. The in-memory cache is currently implemented as a three-dimensional associative array $cache [$langcode] [$component] [$stringid] . When it gets stored Both caches are populated on-the-fly when the given string component is accessed for the first time. If some string from the component mod_bar is requested and the component mod_bar is not loaded into the memory yet, the core_string_manager reads the whole component from the on-disk cache. If the component mod_bar is not found in the on-disk cache yet, all the possible sources of the strings from this component are merged together and stored. Where it gets stored The core_string_manager (which is a singleton) stores the in-memory cache in its protected $this->cache property. The on-disk cache is stored in files in $CFG->langcacheroot which is $CFG->cachedir.'/lang' by default (where $CFG->cachedir itself defaults to $CFG->dataroot.'/cache'). How it gets read In core_string_manager::load_component_strings() that is used by get_string() and friends. Does it need locking? Yes it does. Especially when the on-disk cache is recreated, two concurrent requests may check for the file existence and either try to use the incomplete data or start overwriting the file again. Petr did recently some tweaks to minimize this race conditions (see d7b44d5e959a66cd3da2e212d0ac1bdcf139d075), some solid solution would be nice for sure. How it gets cleared? The in-memory cache is a request cache and is cleared automatically at the end of the request. The on-disk cache is cleared as a part of the purge_all_caches() call. So it can be cleared manually via the Purge all caches feature, is automatically cleared on core upgrades etc. Typical sizes The in-memory cache has typically 600KB - 1MB for students and something about 2MB for admins. Safeguards in place None currently implemented.
              Hide
              samhemelryk Sam Hemelryk added a comment -

              I had this developed for testing, putting it up for peer-review now.

              Show
              samhemelryk Sam Hemelryk added a comment - I had this developed for testing, putting it up for peer-review now.
              Hide
              poltawski Dan Poltawski added a comment -

              Sending all 'waiting for peer review' issues to integration before freeze, as agreed in Integrators Meeting 19/10/12. We are doing this to ensure any 'integratable issues' will not got missed before freeze..

              Show
              poltawski Dan Poltawski added a comment - Sending all 'waiting for peer review' issues to integration before freeze, as agreed in Integrators Meeting 19/10/12. We are doing this to ensure any 'integratable issues' will not got missed before freeze..
              Hide
              poltawski Dan Poltawski added a comment -

              The main moodle.git repository has just been updated with latest weekly modifications. You may wish to rebase your PULL branches to simplify history and avoid any possible merge conflicts. This would also make integrator's life easier next week.

              TIA and ciao

              Show
              poltawski Dan Poltawski added a comment - The main moodle.git repository has just been updated with latest weekly modifications. You may wish to rebase your PULL branches to simplify history and avoid any possible merge conflicts. This would also make integrator's life easier next week. TIA and ciao
              Hide
              poltawski Dan Poltawski added a comment -

              Hi Sam,

              I'm not confident on this change - the performance seems to be much worse on the admin front page in default configuration.

              Without conversion to MUC the front page loads for me in 0.86 secs, with the patch 3.64 secs.

              This large load time is sustained as many times as I refresh it. Here is the perf info from both:

              0.86142 secs
              RAM: 62.9MB
              RAM peak: 63.1MB
              Included 990 files
              Contexts for which filters were loaded: 2
              Filters created: 4
              Pieces of content filtered: 1
              Strings filtered: 0
              get_string calls: 1321
              strings mem cache hits: 2365
              strings disk cache hits: 339
              Included YUI modules: 0
              Other JavaScript modules: 3
              Log DB writes 1
              DB reads/writes: 89/2
              ticks: 86 user: 65 sys: 12 cuser: 0 csys: 0
              Load average: 1.52
              Session: 6.9KB
              Caches interaction by definition then store
              core/databasemeta
              ** static persist **: 44 / 19 / 0
              cachestore_file: 19 / 0 / 0
              Total Hits / Misses / Sets : 63 / 19 / 0

              3.643061 secs
              RAM: 62.8MB
              RAM peak: 63.4MB
              Included 651 files
              Contexts for which filters were loaded: 2
              Filters created: 4
              Pieces of content filtered: 1
              Strings filtered: 0
              get_string calls: 1321
              strings mem cache hits: 0
              strings disk cache hits: 2704
              Included YUI modules: 0
              Other JavaScript modules: 3
              Log DB writes 1
              DB reads/writes: 89/2
              ticks: 365 user: 344 sys: 13 cuser: 0 csys: 0
              Load average: 1.53
              Session: 6.9KB
              Caches interaction by definition then store
              core/databasemeta
              ** static persist **: 44 / 19 / 0
              cachestore_file: 19 / 0 / 0
              core/string
              ** static persist **: 2365 / 339 / 0
              cachestore_file: 339 / 0 / 0
              Total Hits / Misses / Sets : 2767 / 358 / 0

              Show
              poltawski Dan Poltawski added a comment - Hi Sam, I'm not confident on this change - the performance seems to be much worse on the admin front page in default configuration. Without conversion to MUC the front page loads for me in 0.86 secs, with the patch 3.64 secs. This large load time is sustained as many times as I refresh it. Here is the perf info from both: 0.86142 secs RAM: 62.9MB RAM peak: 63.1MB Included 990 files Contexts for which filters were loaded: 2 Filters created: 4 Pieces of content filtered: 1 Strings filtered: 0 get_string calls: 1321 strings mem cache hits: 2365 strings disk cache hits: 339 Included YUI modules: 0 Other JavaScript modules: 3 Log DB writes 1 DB reads/writes: 89/2 ticks: 86 user: 65 sys: 12 cuser: 0 csys: 0 Load average: 1.52 Session: 6.9KB Caches interaction by definition then store core/databasemeta ** static persist **: 44 / 19 / 0 cachestore_file: 19 / 0 / 0 Total Hits / Misses / Sets : 63 / 19 / 0 3.643061 secs RAM: 62.8MB RAM peak: 63.4MB Included 651 files Contexts for which filters were loaded: 2 Filters created: 4 Pieces of content filtered: 1 Strings filtered: 0 get_string calls: 1321 strings mem cache hits: 0 strings disk cache hits: 2704 Included YUI modules: 0 Other JavaScript modules: 3 Log DB writes 1 DB reads/writes: 89/2 ticks: 365 user: 344 sys: 13 cuser: 0 csys: 0 Load average: 1.53 Session: 6.9KB Caches interaction by definition then store core/databasemeta ** static persist **: 44 / 19 / 0 cachestore_file: 19 / 0 / 0 core/string ** static persist **: 2365 / 339 / 0 cachestore_file: 339 / 0 / 0 Total Hits / Misses / Sets : 2767 / 358 / 0
              Hide
              cibot CiBoT added a comment -

              Moving this reopened issue out from current integration. Please, re-submit it for integration once ready.

              Show
              cibot CiBoT added a comment - Moving this reopened issue out from current integration. Please, re-submit it for integration once ready.
              Hide
              samhemelryk Sam Hemelryk added a comment -

              Whoa! those are some pretty gnarly results. I'll run tests and find out what is going wrong there.

              Show
              samhemelryk Sam Hemelryk added a comment - Whoa! those are some pretty gnarly results. I'll run tests and find out what is going wrong there.
              Hide
              samhemelryk Sam Hemelryk added a comment -

              Ok I've tracked down the issue here and created a new bug for it MDL-36362. I've put that up for integration review now as well.
              I'll provide some performance test results shortly.

              Show
              samhemelryk Sam Hemelryk added a comment - Ok I've tracked down the issue here and created a new bug for it MDL-36362 . I've put that up for integration review now as well. I'll provide some performance test results shortly.
              Hide
              samhemelryk Sam Hemelryk added a comment -

              Performance comparison: http://moodev.com/?w=300&h=150&before=MDL-34342-01&after=MDL-34342-02#statsarray

              Run:

              • 15 pages per run
              • 50 users per loop
              • Repeated 5 times
              • Throughput of 220 page requests per second
              • Ramp up period of 2 minutes.
              • Dedicated server running PHP 5.4.5 + PgSQL 9.0.7

              Putting back up for peer-review now.

              IMPORTANT MDL-36362 must be integrated first.

              Show
              samhemelryk Sam Hemelryk added a comment - Performance comparison: http://moodev.com/?w=300&h=150&before=MDL-34342-01&after=MDL-34342-02#statsarray Run: 15 pages per run 50 users per loop Repeated 5 times Throughput of 220 page requests per second Ramp up period of 2 minutes. Dedicated server running PHP 5.4.5 + PgSQL 9.0.7 Putting back up for peer-review now. IMPORTANT MDL-36362 must be integrated first.
              Hide
              poltawski Dan Poltawski added a comment -

              Hi Sam,

              I've tested this on top of MDL-36362 and its still significantly slower for my logged in as admin on /admin/ on my mac (ssd). That page isn't covered by the jmeter tests and I know that is not really our optimised user, but it does suggest the sum of it seems slower.

              I'm testing by refreshing the /admin/ page 10/15 times to ensure the numbers are settled.

              Running on 2c36da50bc18d7e2f941b03146daae2707a0f255 (current integration/master) its consistently ~1s loading:

              1.069883 secs
              RAM: 64.7MB
              RAM peak: 65MB
              Included 1012 files
              Contexts for which filters were loaded: 1
              Filters created: 2
              Pieces of content filtered: 0
              Strings filtered: 0
              get_string calls: 2118
              strings mem cache hits: 3207
              strings disk cache hits: 341
              Included YUI modules: 0
              Other JavaScript modules: 2
              DB reads/writes: 574/0
              ticks: 107 user: 75 sys: 13 cuser: 0 csys: 0
              Load average: 1.29
              Session: 6.9KB
              Caches interaction by definition then store
              core/databasemeta
              ** static persist **: 526 / 21 / 0
              cachestore_file: 21 / 0 / 0
              Total Hits / Misses / Sets : 547 / 21 / 0

              With patch applied its consistently ~4.5s:

              4.643225 secs
              RAM: 64.7MB
              RAM peak: 65.3MB
              Included 671 files
              Contexts for which filters were loaded: 1
              Filters created: 2
              Pieces of content filtered: 0
              Strings filtered: 0
              get_string calls: 2118
              strings mem cache hits: 0
              strings disk cache hits: 3548
              Included YUI modules: 0
              Other JavaScript modules: 2
              DB reads/writes: 574/0
              ticks: 464 user: 432 sys: 15 cuser: 0 csys: 0
              Load average: 1.58
              Session: 6.9KB
              Caches interaction by definition then store
              core/databasemeta
              ** static persist **: 526 / 21 / 0
              cachestore_file: 21 / 0 / 0
              core/string
              ** static persist **: 3207 / 341 / 0
              cachestore_file: 341 / 0 / 0
              Total Hits / Misses / Sets : 4095 / 362 / 0

              Show
              poltawski Dan Poltawski added a comment - Hi Sam, I've tested this on top of MDL-36362 and its still significantly slower for my logged in as admin on /admin/ on my mac (ssd). That page isn't covered by the jmeter tests and I know that is not really our optimised user, but it does suggest the sum of it seems slower. I'm testing by refreshing the /admin/ page 10/15 times to ensure the numbers are settled. Running on 2c36da50bc18d7e2f941b03146daae2707a0f255 (current integration/master) its consistently ~1s loading: 1.069883 secs RAM: 64.7MB RAM peak: 65MB Included 1012 files Contexts for which filters were loaded: 1 Filters created: 2 Pieces of content filtered: 0 Strings filtered: 0 get_string calls: 2118 strings mem cache hits: 3207 strings disk cache hits: 341 Included YUI modules: 0 Other JavaScript modules: 2 DB reads/writes: 574/0 ticks: 107 user: 75 sys: 13 cuser: 0 csys: 0 Load average: 1.29 Session: 6.9KB Caches interaction by definition then store core/databasemeta ** static persist **: 526 / 21 / 0 cachestore_file: 21 / 0 / 0 Total Hits / Misses / Sets : 547 / 21 / 0 With patch applied its consistently ~4.5s: 4.643225 secs RAM: 64.7MB RAM peak: 65.3MB Included 671 files Contexts for which filters were loaded: 1 Filters created: 2 Pieces of content filtered: 0 Strings filtered: 0 get_string calls: 2118 strings mem cache hits: 0 strings disk cache hits: 3548 Included YUI modules: 0 Other JavaScript modules: 2 DB reads/writes: 574/0 ticks: 464 user: 432 sys: 15 cuser: 0 csys: 0 Load average: 1.58 Session: 6.9KB Caches interaction by definition then store core/databasemeta ** static persist **: 526 / 21 / 0 cachestore_file: 21 / 0 / 0 core/string ** static persist **: 3207 / 341 / 0 cachestore_file: 341 / 0 / 0 Total Hits / Misses / Sets : 4095 / 362 / 0
              Hide
              poltawski Dan Poltawski added a comment -

              Sam and I discussed this, and the problem was that my cache definitions weren't reloaded.

              Show
              poltawski Dan Poltawski added a comment - Sam and I discussed this, and the problem was that my cache definitions weren't reloaded.
              Hide
              poltawski Dan Poltawski added a comment -

              After picking up the cache defintion changes performance is equivalent.

              I've integrated this now, thanks Sam.

              I've put some (crappy) testing instructions on this. If you could expand them would be good (I guess testing the invalidation and mechanics when devs adding new strings).

              Show
              poltawski Dan Poltawski added a comment - After picking up the cache defintion changes performance is equivalent. I've integrated this now, thanks Sam. I've put some (crappy) testing instructions on this. If you could expand them would be good (I guess testing the invalidation and mechanics when devs adding new strings).
              Hide
              poltawski Dan Poltawski added a comment -

              Bah, its breaking install:

              Moodle 2.4dev (Build: 20121101) command line installation program
              PHP Fatal error: Class 'cache' not found in /Users/Shared/Jenkins/Home/git_repositories/master/lib/moodlelib.php on line 6492
              PHP Stack trace:
              PHP 1.

              {main}() /Users/Shared/Jenkins/Home/git_repositories/master/admin/cli/install.php:0
              PHP 2. get_string_manager() /Users/Shared/Jenkins/Home/git_repositories/master/admin/cli/install.php:399
              PHP 3. core_string_manager->__construct() /Users/Shared/Jenkins/Home/git_repositories/master/lib/moodlelib.php:6326

              Fatal error: Class 'cache' not found in /Users/Shared/Jenkins/Home/git_repositories/master/lib/moodlelib.php on line 6492

              Call Stack:
              0.0015 992648 1. {main}

              () /Users/Shared/Jenkins/Home/git_repositories/master/admin/cli/install.php:0
              0.0941 24019352 2. get_string_manager() /Users/Shared/Jenkins/Home/git_repositories/master/admin/cli/install.php:399
              0.0941 24020544 3. core_string_manager->__construct() /Users/Shared/Jenkins/Home/git_repositories/master/lib/moodlelib.php:6326

              Show
              poltawski Dan Poltawski added a comment - Bah, its breaking install: Moodle 2.4dev (Build: 20121101) command line installation program PHP Fatal error: Class 'cache' not found in /Users/Shared/Jenkins/Home/git_repositories/master/lib/moodlelib.php on line 6492 PHP Stack trace: PHP 1. {main}() /Users/Shared/Jenkins/Home/git_repositories/master/admin/cli/install.php:0 PHP 2. get_string_manager() /Users/Shared/Jenkins/Home/git_repositories/master/admin/cli/install.php:399 PHP 3. core_string_manager->__construct() /Users/Shared/Jenkins/Home/git_repositories/master/lib/moodlelib.php:6326 Fatal error: Class 'cache' not found in /Users/Shared/Jenkins/Home/git_repositories/master/lib/moodlelib.php on line 6492 Call Stack: 0.0015 992648 1. {main} () /Users/Shared/Jenkins/Home/git_repositories/master/admin/cli/install.php:0 0.0941 24019352 2. get_string_manager() /Users/Shared/Jenkins/Home/git_repositories/master/admin/cli/install.php:399 0.0941 24020544 3. core_string_manager->__construct() /Users/Shared/Jenkins/Home/git_repositories/master/lib/moodlelib.php:6326
              Hide
              andyjdavis Andrew Davis added a comment -

              This appears to be causing the following PHP notice.

              Notice: Undefined property: core_string_manager::$usediskcache in /home/andrew/Desktop/code/moodle/int/master/lib/moodlelib.php on line 7033

              If you go to course > participants, select a user and select "send a message" you get taken to a page containing this notice.

              Show
              andyjdavis Andrew Davis added a comment - This appears to be causing the following PHP notice. Notice: Undefined property: core_string_manager::$usediskcache in /home/andrew/Desktop/code/moodle/int/master/lib/moodlelib.php on line 7033 If you go to course > participants, select a user and select "send a message" you get taken to a page containing this notice.
              Hide
              samhemelryk Sam Hemelryk added a comment -

              Hi Dan,

              I've got a branch to fix both the CLI install and the warning Andrew mentioned.

              git fetch git://github.com/samhemelryk/moodle.git wip-MDL-34342-m24-p1;

              Cheers
              Sam

              Show
              samhemelryk Sam Hemelryk added a comment - Hi Dan, I've got a branch to fix both the CLI install and the warning Andrew mentioned. git fetch git://github.com/samhemelryk/moodle.git wip- MDL-34342 -m24-p1; Cheers Sam
              Hide
              poltawski Dan Poltawski added a comment -

              Thanks Sam, i've pulled that in.

              Show
              poltawski Dan Poltawski added a comment - Thanks Sam, i've pulled that in.
              Hide
              andyjdavis Andrew Davis added a comment -

              Not sure if this is related (and I dont have any hard numbers) but my integration test site seemed to be running very slowly. Going to Home ▶ Site administration ▶ Plugins ▶ Caching ▶ Configuration and clicking 'Rescan definitions' seemed to speed things up.

              Show
              andyjdavis Andrew Davis added a comment - Not sure if this is related (and I dont have any hard numbers) but my integration test site seemed to be running very slowly. Going to Home ▶ Site administration ▶ Plugins ▶ Caching ▶ Configuration and clicking 'Rescan definitions' seemed to speed things up.
              Hide
              poltawski Dan Poltawski added a comment -

              Andrew, I created an issue for that now: MDL-36386

              Show
              poltawski Dan Poltawski added a comment - Andrew, I created an issue for that now: MDL-36386
              Hide
              abgreeve Adrian Greeve added a comment -

              I browsed around the site, installed a language pack and did some more browsing. Introduced a few new strings, and tested them out in different areas (including index.php).
              The version number was incremented.
              All strings loaded as expected.
              Test passed.

              Show
              abgreeve Adrian Greeve added a comment - I browsed around the site, installed a language pack and did some more browsing. Introduced a few new strings, and tested them out in different areas (including index.php). The version number was incremented. All strings loaded as expected. Test passed.
              Hide
              stronk7 Eloy Lafuente (stronk7) added a comment -

              Amazed. Inspired. Grateful. That’s how your generosity makes me feel.

              (not really)

              Closing, thanks!

              Show
              stronk7 Eloy Lafuente (stronk7) added a comment - Amazed. Inspired. Grateful. That’s how your generosity makes me feel. (not really) Closing, thanks!

                People

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

                  Dates

                  • Created:
                    Updated:
                    Resolved:
                    Fix Release Date:
                    3/Dec/12