Moodle
  1. Moodle
  2. MDL-35257

Guess last access record is being updated when autologged in.. can lead to contention

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 2.2.5, 2.3.1, 2.4
    • Fix Version/s: 2.2.6, 2.3.3
    • Component/s: Performance
    • Labels:
    • Testing Instructions:
      Hide
      • Install Moodle 2.3
      • Create a course, set 'allow guest access' to yes
      • Add a forum to the course
      • In Admin > Users > Permissions > User Policies, switch on 'autologinguests'
      • Put the attached 'testguest.php' file in your moodle directory
      • Run testguest.php and note the various times.

      Open a new incognito browser (something not logged into your moodle):

      • Visit your moodle site
      • Click onto the course

      In your admin user browser:

      • Run testguest.php again and verify the various times have not changed

      In your inconginto browser:

      • Wait 60 seconds, then click around the course

      In your admin user browser:

      • Run testguest.php again and verify the various times have not changed
      Show
      Install Moodle 2.3 Create a course, set 'allow guest access' to yes Add a forum to the course In Admin > Users > Permissions > User Policies, switch on 'autologinguests' Put the attached 'testguest.php' file in your moodle directory Run testguest.php and note the various times. Open a new incognito browser (something not logged into your moodle): Visit your moodle site Click onto the course In your admin user browser: Run testguest.php again and verify the various times have not changed In your inconginto browser: Wait 60 seconds, then click around the course In your admin user browser: Run testguest.php again and verify the various times have not changed
    • Affected Branches:
      MOODLE_22_STABLE, MOODLE_23_STABLE, MOODLE_24_STABLE
    • Fixed Branches:
      MOODLE_22_STABLE, MOODLE_23_STABLE
    • Pull Master Branch:
      MDL-35257-master
    • Rank:
      43909

      Description

      On moodle.org, we are seeing high contention on the guest record causing lock timeouts.

      user_accesstime_log() does do nothing if the user is '!isloggedin()', but I suppose that when a guest is auto logged in then this doesn't apply.

      I think we should just check for the guest user and not update these fields if guest.

        Issue Links

          Activity

          Hide
          Dan Poltawski added a comment -

          Also discovered is the lastlogin one:

          UPDATE user SET lastlogin = ?,currentlogin = ?,lastaccess = ? WHERE id=?

          Show
          Dan Poltawski added a comment - Also discovered is the lastlogin one: UPDATE user SET lastlogin = ?,currentlogin = ?,lastaccess = ? WHERE id=?
          Hide
          Dan Poltawski added a comment -

          We have '$CFG->logguests' logic elsewhere, so should probably apply this here too.

          Show
          Dan Poltawski added a comment - We have '$CFG->logguests' logic elsewhere, so should probably apply this here too.
          Hide
          Dan Poltawski added a comment -

          Examined the postgres query log and played around, with my patch and 'log guests' set to on you get the following INSERT/UPDATES for a typical course/forum view as guest:

          LOG:  duration: 0.231 ms  parse <unnamed>: UPDATE m0x_user SET lastip = $1,lastaccess = $2 WHERE id=$3
          LOG:  duration: 0.787 ms  bind <unnamed>: UPDATE m0x_user SET lastip = $1,lastaccess = $2 WHERE id=$3
          LOG:  duration: 0.430 ms  execute <unnamed>: UPDATE m0x_user SET lastip = $1,lastaccess = $2 WHERE id=$3
          LOG:  duration: 0.047 ms  parse <unnamed>: UPDATE m0x_user_lastaccess SET timeaccess = $3 WHERE userid = $1 AND courseid = $2
          LOG:  duration: 0.089 ms  bind <unnamed>: UPDATE m0x_user_lastaccess SET timeaccess = $3 WHERE userid = $1 AND courseid = $2
          LOG:  duration: 0.065 ms  execute <unnamed>: UPDATE m0x_user_lastaccess SET timeaccess = $3 WHERE userid = $1 AND courseid = $2
          LOG:  duration: 0.266 ms  parse <unnamed>: INSERT INTO m0x_log (time,userid,course,ip,module,cmid,action,url,info) VALUES($1,$2,$3,$4,$5,$6,$7,$8,$9) 
          LOG:  duration: 0.116 ms  bind <unnamed>: INSERT INTO m0x_log (time,userid,course,ip,module,cmid,action,url,info) VALUES($1,$2,$3,$4,$5,$6,$7,$8,$9) 
          LOG:  duration: 0.570 ms  execute <unnamed>: INSERT INTO m0x_log (time,userid,course,ip,module,cmid,action,url,info) VALUES($1,$2,$3,$4,$5,$6,$7,$8,$9) 
          LOG:  duration: 0.165 ms  parse <unnamed>: UPDATE m0x_sessions SET state = $1,sid = $2,userid = $3,timecreated = $4,timemodified = $5,firstip = $6,lastip = $7,sessdata = $8 WHERE id=$9
          LOG:  duration: 0.188 ms  bind <unnamed>: UPDATE m0x_sessions SET state = $1,sid = $2,userid = $3,timecreated = $4,timemodified = $5,firstip = $6,lastip = $7,sessdata = $8 WHERE id=$9
          LOG:  duration: 1.221 ms  execute <unnamed>: UPDATE m0x_sessions SET state = $1,sid = $2,userid = $3,timecreated = $4,timemodified = $5,firstip = $6,lastip = $7,sessdata = $8 WHERE id=$9
          

          When logguests is switched off that change to just:

          LOG:  duration: 0.277 ms  parse <unnamed>: INSERT INTO m0x_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
          LOG:  duration: 0.137 ms  bind <unnamed>: INSERT INTO m0x_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
          LOG:  duration: 1.755 ms  execute <unnamed>: INSERT INTO m0x_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
          
          Show
          Dan Poltawski added a comment - Examined the postgres query log and played around, with my patch and 'log guests' set to on you get the following INSERT/UPDATES for a typical course/forum view as guest: LOG: duration: 0.231 ms parse <unnamed>: UPDATE m0x_user SET lastip = $1,lastaccess = $2 WHERE id=$3 LOG: duration: 0.787 ms bind <unnamed>: UPDATE m0x_user SET lastip = $1,lastaccess = $2 WHERE id=$3 LOG: duration: 0.430 ms execute <unnamed>: UPDATE m0x_user SET lastip = $1,lastaccess = $2 WHERE id=$3 LOG: duration: 0.047 ms parse <unnamed>: UPDATE m0x_user_lastaccess SET timeaccess = $3 WHERE userid = $1 AND courseid = $2 LOG: duration: 0.089 ms bind <unnamed>: UPDATE m0x_user_lastaccess SET timeaccess = $3 WHERE userid = $1 AND courseid = $2 LOG: duration: 0.065 ms execute <unnamed>: UPDATE m0x_user_lastaccess SET timeaccess = $3 WHERE userid = $1 AND courseid = $2 LOG: duration: 0.266 ms parse <unnamed>: INSERT INTO m0x_log (time,userid,course,ip,module,cmid,action,url,info) VALUES($1,$2,$3,$4,$5,$6,$7,$8,$9) LOG: duration: 0.116 ms bind <unnamed>: INSERT INTO m0x_log (time,userid,course,ip,module,cmid,action,url,info) VALUES($1,$2,$3,$4,$5,$6,$7,$8,$9) LOG: duration: 0.570 ms execute <unnamed>: INSERT INTO m0x_log (time,userid,course,ip,module,cmid,action,url,info) VALUES($1,$2,$3,$4,$5,$6,$7,$8,$9) LOG: duration: 0.165 ms parse <unnamed>: UPDATE m0x_sessions SET state = $1,sid = $2,userid = $3,timecreated = $4,timemodified = $5,firstip = $6,lastip = $7,sessdata = $8 WHERE id=$9 LOG: duration: 0.188 ms bind <unnamed>: UPDATE m0x_sessions SET state = $1,sid = $2,userid = $3,timecreated = $4,timemodified = $5,firstip = $6,lastip = $7,sessdata = $8 WHERE id=$9 LOG: duration: 1.221 ms execute <unnamed>: UPDATE m0x_sessions SET state = $1,sid = $2,userid = $3,timecreated = $4,timemodified = $5,firstip = $6,lastip = $7,sessdata = $8 WHERE id=$9 When logguests is switched off that change to just: LOG: duration: 0.277 ms parse <unnamed>: INSERT INTO m0x_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id LOG: duration: 0.137 ms bind <unnamed>: INSERT INTO m0x_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id LOG: duration: 1.755 ms execute <unnamed>: INSERT INTO m0x_sessions (state,sid,sessdata,userid,timemodified,timecreated,lastip,firstip) VALUES($1,$2,$3,$4,$5,$6,$7,$8) RETURNING id
          Hide
          Frédéric Massart added a comment -

          Hi guys, my thought on this is that maybe we should avoid logging the information regardless of $CFG->logguests.

          IMO updating those fields in the database should not be considered as a log. Plus, accessing the last access time or last login time of the guest user is quite tricky through the user interface and I assume that nobody really looks for this information. And if this is really needed, then the access logs are probably much more accurate.

          If we really want to keep track of one of them, I'd keep the last access time of a course, not the login one as it's sort of redundant.

          Show
          Frédéric Massart added a comment - Hi guys, my thought on this is that maybe we should avoid logging the information regardless of $CFG->logguests. IMO updating those fields in the database should not be considered as a log. Plus, accessing the last access time or last login time of the guest user is quite tricky through the user interface and I assume that nobody really looks for this information. And if this is really needed, then the access logs are probably much more accurate. If we really want to keep track of one of them, I'd keep the last access time of a course, not the login one as it's sort of redundant.
          Hide
          Dan Poltawski added a comment -

          I think I agree with Fred, it was discussing it with Eloy that I ended up adding the check on logging item. But it doesn't seem possible to examine these records anyway, so it would make sense to avoid it.

          Show
          Dan Poltawski added a comment - I think I agree with Fred, it was discussing it with Eloy that I ended up adding the check on logging item. But it doesn't seem possible to examine these records anyway, so it would make sense to avoid it.
          Hide
          Martin Dougiamas added a comment -

          While technically it's not a log I think it was pretty reasonable to link that setting to that behaviour.

          The only time I thought they might be used is in the Online Users block but just checked and no, not shown there.

          So actually yeah my +1 for not updating those fields any time. That should save a lot of CPU.

          Show
          Martin Dougiamas added a comment - While technically it's not a log I think it was pretty reasonable to link that setting to that behaviour. The only time I thought they might be used is in the Online Users block but just checked and no, not shown there. So actually yeah my +1 for not updating those fields any time. That should save a lot of CPU.
          Hide
          Dan Poltawski added a comment -

          Ok, updated my patch to do that.

          Show
          Dan Poltawski added a comment - Ok, updated my patch to do that.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Integrated (22, 23 & master), thanks!

          Show
          Eloy Lafuente (stronk7) added a comment - Integrated (22, 23 & master), thanks!
          Hide
          Eloy Lafuente (stronk7) added a comment -

          I'm getting onto this. I'm sure it works... but let's follow Dan's instructions, the "incognito" word called my attention and I'm curious, lol.

          Show
          Eloy Lafuente (stronk7) added a comment - I'm getting onto this. I'm sure it works... but let's follow Dan's instructions, the "incognito" word called my attention and I'm curious, lol.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Confirmed, both user and user_lastaccess remain unmodified now under guest browsing.

          Offtopic: I noticed there is an small difference between update_user_login_times() and user_accesstime_log(). The later looks for isloggedin() and session_is_loggedinas() and the former is missing those checks (just guessing if it would be necessary to add them.

          Passing, anyway... thanks!

          Show
          Eloy Lafuente (stronk7) added a comment - Confirmed, both user and user_lastaccess remain unmodified now under guest browsing. Offtopic: I noticed there is an small difference between update_user_login_times() and user_accesstime_log(). The later looks for isloggedin() and session_is_loggedinas() and the former is missing those checks (just guessing if it would be necessary to add them. Passing, anyway... thanks!
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Gutta cavat lapidem, non vi sed saepe cadendo - Ovidio

          This issue has been integrated upstream and is now available both via git and cvs (and in some hours, via mirrors and downloads).

          Thanks!

          Show
          Eloy Lafuente (stronk7) added a comment - Gutta cavat lapidem, non vi sed saepe cadendo - Ovidio This issue has been integrated upstream and is now available both via git and cvs (and in some hours, via mirrors and downloads). Thanks!

            People

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

              Dates

              • Created:
                Updated:
                Resolved: