search

moodleou / moodle-qtype_opaque

The Opaque question type for Moodle. Allows Moodle to use any other question engine via a web-service link.
7 stars 12 forks source link

Poor performance of OPAQUE questions due to excessive replays #2

Closed anttix closed 12 years ago

anttix commented 12 years ago

Hi!

I have noticed that the new OPAQUE module will replay an entire question session twice for every user input. Also in the beginning, the session is started four times in a row.

Below is a log from my testing engine (available from http://ounit.googlecode.com) that was generated when attempting a single question quiz (the numbers 9, 8, 7, 6, 5, 4, 3 were entered into the input box).

DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: stop(135e5f6b)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: stop(451cc05e)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: stop(e056d6b2)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour, display_readonly, display_marks, display_markdp, display_correctness, display_feedback, display_generalfeedback],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback, 0, 2, 2, 1, 1, 1],[mockpic.gif, mockscript.js])
DEBUG: stop(409e4575)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: process(65a20894, [nr, go], [9, Go])
DEBUG: stop(65a20894)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour, display_readonly, display_marks, display_markdp, display_correctness, display_feedback, display_generalfeedback],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback, 0, 2, 2, 1, 1, 1],[mockpic.gif, mockscript.js])
DEBUG: process(ef5adea0, [nr, go], [9, Go])
DEBUG: stop(ef5adea0)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: process(32968219, [nr, go], [9, Go])
DEBUG: process(32968219, [nr, go], [8, Go])
DEBUG: stop(32968219)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour, display_readonly, display_marks, display_markdp, display_correctness, display_feedback, display_generalfeedback],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback, 0, 2, 2, 1, 1, 1],[mockpic.gif, mockscript.js])
DEBUG: process(2262b3f4, [nr, go], [9, Go])
DEBUG: process(2262b3f4, [nr, go], [8, Go])
DEBUG: stop(2262b3f4)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: process(e9606339, [nr, go], [9, Go])
DEBUG: process(e9606339, [nr, go], [8, Go])
DEBUG: process(e9606339, [nr, go], [7, Go])
DEBUG: stop(e9606339)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour, display_readonly, display_marks, display_markdp, display_correctness, display_feedback, display_generalfeedback],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback, 0, 2, 2, 1, 1, 1],[mockpic.gif, mockscript.js])
DEBUG: process(7f7b1b6b, [nr, go], [9, Go])
DEBUG: process(7f7b1b6b, [nr, go], [8, Go])
DEBUG: process(7f7b1b6b, [nr, go], [7, Go])
DEBUG: stop(7f7b1b6b)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: process(c41f9ecd, [nr, go], [9, Go])
DEBUG: process(c41f9ecd, [nr, go], [8, Go])
DEBUG: process(c41f9ecd, [nr, go], [7, Go])
DEBUG: process(c41f9ecd, [nr, go], [6, Go])
DEBUG: stop(c41f9ecd)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour, display_readonly, display_marks, display_markdp, display_correctness, display_feedback, display_generalfeedback],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback, 0, 2, 2, 1, 1, 1],[mockpic.gif, mockscript.js])
DEBUG: process(189ee74a, [nr, go], [9, Go])
DEBUG: process(189ee74a, [nr, go], [8, Go])
DEBUG: process(189ee74a, [nr, go], [7, Go])
DEBUG: process(189ee74a, [nr, go], [6, Go])
DEBUG: stop(189ee74a)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: process(1f800ef6, [nr, go], [9, Go])
DEBUG: process(1f800ef6, [nr, go], [8, Go])
DEBUG: process(1f800ef6, [nr, go], [7, Go])
DEBUG: process(1f800ef6, [nr, go], [6, Go])
DEBUG: process(1f800ef6, [nr, go], [5, Go])
DEBUG: stop(1f800ef6)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour, display_readonly, display_marks, display_markdp, display_correctness, display_feedback, display_generalfeedback],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback, 0, 2, 2, 1, 1, 1],[mockpic.gif, mockscript.js])
DEBUG: process(7d0bb59c, [nr, go], [9, Go])
DEBUG: process(7d0bb59c, [nr, go], [8, Go])
DEBUG: process(7d0bb59c, [nr, go], [7, Go])
DEBUG: process(7d0bb59c, [nr, go], [6, Go])
DEBUG: process(7d0bb59c, [nr, go], [5, Go])
DEBUG: stop(7d0bb59c)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: process(e8ddd700, [nr, go], [9, Go])
DEBUG: process(e8ddd700, [nr, go], [8, Go])
DEBUG: process(e8ddd700, [nr, go], [7, Go])
DEBUG: process(e8ddd700, [nr, go], [6, Go])
DEBUG: process(e8ddd700, [nr, go], [5, Go])
DEBUG: process(e8ddd700, [nr, go], [4, Go])
DEBUG: stop(e8ddd700)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour, display_readonly, display_marks, display_markdp, display_correctness, display_feedback, display_generalfeedback],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback, 0, 2, 2, 1, 1, 1],[mockpic.gif, mockscript.js])
DEBUG: process(1b44f87b, [nr, go], [9, Go])
DEBUG: process(1b44f87b, [nr, go], [8, Go])
DEBUG: process(1b44f87b, [nr, go], [7, Go])
DEBUG: process(1b44f87b, [nr, go], [6, Go])
DEBUG: process(1b44f87b, [nr, go], [5, Go])
DEBUG: process(1b44f87b, [nr, go], [4, Go])
DEBUG: stop(1b44f87b)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: process(9a1dc8cd, [nr, go], [9, Go])
DEBUG: process(9a1dc8cd, [nr, go], [8, Go])
DEBUG: process(9a1dc8cd, [nr, go], [7, Go])
DEBUG: process(9a1dc8cd, [nr, go], [6, Go])
DEBUG: process(9a1dc8cd, [nr, go], [5, Go])
DEBUG: process(9a1dc8cd, [nr, go], [4, Go])
DEBUG: process(9a1dc8cd, [nr, go], [3, Go])
DEBUG: stop(9a1dc8cd)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour, display_readonly, display_marks, display_markdp, display_correctness, display_feedback, display_generalfeedback],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback, 1, 2, 2, 1, 1, 1],[mockpic.gif, mockscript.js])
DEBUG: process(f06c79c4, [nr, go], [9, Go])
DEBUG: process(f06c79c4, [nr, go], [8, Go])
DEBUG: process(f06c79c4, [nr, go], [7, Go])
DEBUG: process(f06c79c4, [nr, go], [6, Go])
DEBUG: process(f06c79c4, [nr, go], [5, Go])
DEBUG: process(f06c79c4, [nr, go], [4, Go])
DEBUG: process(f06c79c4, [nr, go], [3, Go])
DEBUG: stop(f06c79c4)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback],[mockpic.gif, mockscript.js])
DEBUG: process(a8ca920f, [nr, go], [9, Go])
DEBUG: process(a8ca920f, [nr, go], [8, Go])
DEBUG: process(a8ca920f, [nr, go], [7, Go])
DEBUG: process(a8ca920f, [nr, go], [6, Go])
DEBUG: process(a8ca920f, [nr, go], [5, Go])
DEBUG: process(a8ca920f, [nr, go], [4, Go])
DEBUG: process(a8ca920f, [nr, go], [3, Go])
DEBUG: stop(a8ca920f)
DEBUG: start(opw.selftest.v1, 0.1,,[randomseed, userid, language, passKey, preferredbehaviour, display_readonly, display_marks, display_markdp, display_correctness, display_feedback, display_generalfeedback],[1316821364220, 2, et, d7976e7665a7e0db7ebc19973baae0bb, immediatefeedback, 1, 2, 2, 1, 1, 1],[mockpic.gif, mockscript.js])
DEBUG: process(6de5120e, [nr, go], [9, Go])
DEBUG: process(6de5120e, [nr, go], [8, Go])
DEBUG: process(6de5120e, [nr, go], [7, Go])
DEBUG: process(6de5120e, [nr, go], [6, Go])
DEBUG: process(6de5120e, [nr, go], [5, Go])
DEBUG: process(6de5120e, [nr, go], [4, Go])
DEBUG: process(6de5120e, [nr, go], [3, Go])
anttix commented 12 years ago

I have tracked the problem down and I am trying to fix it in my fork, however I am running into difficulties.

The first problem is that when qtype_opaque_update_state is called from behaviour's init_first_step, the question attempt is not saved into the database yet so qaid will be null. Also get_field_prefix will return a temporary random string that will change later on.

Are field prefixes guaranteed to be stable or can they change? If they can change, I will try to rewrite the code to cache raw html and replace placeholders just before rendering.

The call from init_first_step is only made to save status messages. Is it OK to delay that operation until the question is rendered for the first time?

The second problem is the passing of display options to the server. This is the main reason behind the current behaviour (when called from controls and later from render the options change). I was able to reduce the number of replays in my fork by working around it but when the question is closed (results passed) the options change and a full replay is performed.

Is anybody actually using these options now? I think that passing display options to QE as init parameters is wrong, display options do change during the question attempt so the correct way to support them would be to create a new call in the protocol eg. setSessionOptions(sessId, opts []) so engines that do support this feature can handle it intelligently and others do not suffer increased number of replays.

Please let me know what is Your opinion about this and I shall try to implement the optimizations.

timhunt commented 12 years ago

I created http://tracker.moodle.org/browse/CONTRIB-3179 which I think is a better place to discuss this.