Experimenting with get_string

Experimenting with get_string

by Tim Hunt -
Number of replies: 4
Picture of Core developers Picture of Documentation writers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers
I have been playing around with refactoring get_string, since the code in there was a bit of a mess, with quite a lot of duplication, and some complicated logic that I was not sure was correct.

The results are in MDL-18669, including a patch against HEAD.

Included in the patch is a new script lib/simpletest/getstringperformancetester.php. That does some simple performance measurements on get_string. On my system, my new code it a little bit faster than the old code (by about 4%).

However, I now have some doubts about whether that testing script is really measuring the right thing. It is getting the same string from the same file 20000 times, wheras typical Moodle pages get a lot of different strings from a few different files.


So, really, I would like to ask you to do two different things, if you have the time and inclination:

1. Apply the patch to your HEAD install, and run the test script. Then switch back to the un-modified moodlelib.php, and get the same timings for the old code. Please report how the times change, and what sort of hardware and OS you are using.

2. Review the test script, and if you think we should be measuring something else, please make suggestions. (Feel free to edit the script if you like.)
Average of ratings: -
In reply to Tim Hunt

Re: Experimenting with get_string

by Martín Langhoff -
it is good to hear that get_string() is fast with stuff that is already in mem... the trick I guess it to see whether...

- it is fast when reading from many files, as you point out
- it is memory efficient when reading a large # of strings from many files

I am not sure what is the mem footprint of the arrays it builds. Maybe it is all tiny, and not worth our time. But in some cases we loop over modules' string sets (like listing the "new module instance"dropdown boxes in course/index.php) - so all the modules' strings get pulled in.

Perhaps just building that dropdown box is a good test of disk io and memory footprint?

The "pick your language" dropdown used to be a major problem until we started caching it. Perhaps it could be another candidate...
Average of ratings: -
In reply to Martín Langhoff

Re: Experimenting with get_string

by Nicolas Dunand -
Picture of Core developers Picture of Plugin developers
Hi Tim,

My setup is :
  • VMware virtual Machine, 1GB RAM (dev server), i686-type single CPU
  • OS Debian 5.0 (2.6.26 kernel / i686)
  • Apache 2.2.9
  • PHP 5.2.9
  • MySQL 5.1.32
  • Moodle HEAD (20090325)
getstringperformancetester.php results are :
  • with patch :
'en_utf8','info','2.6557269096375','7530.8948097869','1.3567571640015','14741.031431899','1.3738849163055','14557.260046046' 'en_utf8','attemptquiznow','1.4848110675812','13469.727183931','1.4881439208984','13439.560326884','1.5001118183136','13332.339466856' 'en_utf8','fullnamedisplay','1.7103509902954','11693.506253091','1.7090950012207','11702.099640871','1.711452960968','11685.977035961' 'en_utf8','stringthatdoesnotexistinanyfile','1.7864639759064','11195.299916335','1.7809598445892','11229.899461665','1.7915899753571','11163.268535265' 'fr_utf8','info','1.1376359462738','17580.316502399','1.1263511180878','17756.45238756','1.1268980503082','17747.834415482' 'fr_utf8','attemptquiznow','1.2704482078552','15742.475668303','1.2770638465881','15660.924121713','1.2689290046692','15761.323073558' 'fr_utf8','fullnamedisplay','1.4764220714569','13546.261862818','1.4780600070953','13531.250357896','1.4733920097351','13574.120035846' 'fr_utf8','stringthatdoesnotexistinanyfile','2.7283389568329','7330.4674809234','2.7409150600433','7296.8331968973','2.7111749649048','7376.8754355189' 'fr_ca_utf8','info','2.0770199298859','9629.1805929368','2.087709903717','9579.8750412551','2.0926868915558','9557.0914505663' 'fr_ca_utf8','attemptquiznow','2.4306600093842','8228.2178185288','2.4075338840485','8307.255873952','2.394122838974','8353.7902376684' 'fr_ca_utf8','fullnamedisplay','2.4275090694427','8238.8981576869','2.4254729747772','8245.8144073269','2.4265401363373','8242.1880027869' 'fr_ca_utf8','stringthatdoesnotexistinanyfile','2.7288730144501','7329.032862319','2.7187440395355','7356.3379667829','2.7109100818634','7377.5962300648' 'nonexistant','info','2.0627899169922','9695.6068261001','2.067202091217','9674.9128133018','2.057097196579','9722.4380225012' 'nonexistant','attemptquiznow','2.4027378559113','8323.8377215374','2.3999271392822','8333.5863296173','2.4043219089508','8318.3536803221' 'nonexistant','fullnamedisplay','2.4210970401764','8260.718041497','2.4225311279297','8255.8278692139','2.4279119968414','8237.5308602696' 'nonexistant','stringthatdoesnotexistinanyfile','2.7174000740051','7359.9762476352','2.7126989364624','7372.7311686426','2.7070009708405','7388.2500285142'
  • without patch :
'en_utf8','info','2.6472389698029','7555.0413952577','1.3507630825043','14806.445526273','1.3460469245911','14858.323015801' 'en_utf8','attemptquiznow','1.4834270477295','13482.29427973','1.4889590740204','13432.202636703','1.4871718883514','13448.344577149' 'en_utf8','fullnamedisplay','1.7115480899811','11685.327521368','1.7075388431549','11712.764298262','1.7024009227753','11748.11393276' 'en_utf8','stringthatdoesnotexistinanyfile','1.7655961513519','11327.61871093','1.7776720523834','11250.669083302','1.7672691345215','11316.895434501' 'fr_utf8','info','1.1246380805969','17783.498838475','1.1298320293427','17701.746348646','1.1308259963989','17686.186967482' 'fr_utf8','attemptquiznow','1.2667050361633','15788.995408574','1.2762088775635','15671.415825115','1.272579908371','15716.105423668' 'fr_utf8','fullnamedisplay','1.5184800624847','13171.065260662','1.4906861782074','13416.640130152','1.4865090847015','13454.340915794' 'fr_utf8','stringthatdoesnotexistinanyfile','2.7055439949036','7392.2287117393','2.7184088230133','7357.2451026076','2.7219641208649','7347.6354249832' 'fr_ca_utf8','info','2.0785210132599','9622.2265122221','2.0698781013489','9662.4047507757','2.0689759254456','9666.6180374685' 'fr_ca_utf8','attemptquiznow','2.4178631305695','8271.766812247','2.4134140014648','8287.015815712','2.4041330814362','8319.0070277027' 'fr_ca_utf8','fullnamedisplay','2.4323179721832','8222.6091443333','2.4415910243988','8191.3800469203','2.4445400238037','8181.4982799422' 'fr_ca_utf8','stringthatdoesnotexistinanyfile','2.7223188877106','7346.6778966588','2.7168469429016','7361.4746875066','2.7273869514465','7333.0262100845' 'nonexistant','info','2.0919830799103','9560.3067692392','2.0994219779968','9526.4316605293','2.0884711742401','9576.3830723098' 'nonexistant','attemptquiznow','3.5176780223846','5685.5686827306','3.0286729335785','6603.5522615409','3.786936044693','5281.3144357238' 'nonexistant','fullnamedisplay','2.4655869007111','8111.6589296577','2.723335981369','7343.9341075889','2.4247860908508','8248.1502494029' 'nonexistant','stringthatdoesnotexistinanyfile','2.7261929512024','7336.2378811738','2.739119052887','7301.6176419643','2.7455987930298','7284.38548661' ;

Sorry if I can't get in depth into your getstringperformancetester.php script now, but I hope the raw data might help you a little.
Average of ratings: -
In reply to Martín Langhoff

Re: Experimenting with get_string

by Tim Hunt -
Picture of Core developers Picture of Documentation writers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers
Yes, it occurred to me that I should probably record the list of get string calls that requesting, say, the course page with editing on does, and then play that back and time it.

I am not changing the caching strategy, so I don't plan to start measuring memory footprint now. Sorry.
Average of ratings: -
In reply to Tim Hunt

Re: Experimenting with get_string

by Tim Hunt -
Picture of Core developers Picture of Documentation writers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers
OK, I think I have finished experimenting, and I think I have made get_string significantly faster, while at the same time making the code easier to read and less buggy in weird cases.

It would be really great if people could try the latest patch from MDL-18669 and let me know how the timings from my test script look on your hardware. The numbers for my desktop linux machine are at the end of this message. (The timing script now plays back the sequence of get_string calls from two Moodle pages. It does each one three times with each of the old and new get_string implementations, and does that for a range of languages.) As you can see the times fluctuate quite a lot, they also fluctuate if you hit reload, but the savings still seem pretty good.

Also, if you know any weird edge-cases that have revealed bugs in get_string in the past, I would be grateful if you could have a look at the unit tests I wrote, and see if I have covered them.

I hope to commit this to HEAD on Monday, if nobody finds any problems.



Playing back calls from admin_index.php_get_string.log.php

Time for admin_index.php_get_string.log.php: 0.142s.
Time for admin_index.php_get_string.log.php: 0.172s.
Time for admin_index.php_get_string.log.php: 0.144s.

Playing back calls from course_view.php_get_string.log.php

Time for course_view.php_get_string.log.php: 0.016s.
Time for course_view.php_get_string.log.php: 0.016s.
Time for course_view.php_get_string.log.php: 0.015s.

Playing back calls from admin_index.php_old_get_string.log.php

Time for admin_index.php_old_get_string.log.php: 0.228s.
Time for admin_index.php_old_get_string.log.php: 0.232s.
Time for admin_index.php_old_get_string.log.php: 0.252s.

Playing back calls from course_view.php_old_get_string.log.php

Time for course_view.php_old_get_string.log.php: 0.035s.
Time for course_view.php_old_get_string.log.php: 0.035s.
Time for course_view.php_old_get_string.log.php: 0.034s.
Average of ratings: -