General developer forum

 
 
Picture of Chris Sequeira
Timestamps in mdl_user and mdl_log don't match
 

While poking around in the tables on my test 2.3.3 install, I noticed that the timestamps in the mdl_user and mdl_log practically never match (see pic).

I was comparing mdl_user's first and last access for a given user & mdl_log's time stamps for any action logged for that user. Except for admin's firstaccess, all the times in mdl_log trailed by a few seconds to several minutes.

Puzzled, I checked my 2.2.1 Moodle and noticed the same thing.

Why would this be? Is there any user action that would update the "access" fields in mdl_user and mdl_user_lastaccess, but that would not be recorded in mdl_log?

Also, since authentication is always the first action that actually identifies a user to Moodle, wouldn't that timestamp always be identical in mdl_user's "first access" field and the first mdl_log record for that user (the "login" action)?

 


 
Average of ratings: -
Picture of Darko Miletić
Re: Timestamps in mdl_user and mdl_log don't match
Group DevelopersGroup Particularly helpful Moodlers

Stamps in user table are added by update_user_login_times function while timestamps in log table are added by add_to_log function. These changes happen in different places and thus potentialy can be executed in notably different time. It is still rather change that there is such time difference between execution of add_to_log and complete_user_login.

For the details of the process check /login/index.php

/// Let's get them all set up.
add_to_log(SITEID, 'user', 'login', "view.php?id=$USER->id&course=".SITEID,
$user->id, 0, $user->id);
complete_user_login($user);

You might have some slowdown on your server so check the state of your server partitions, file integrity and database status, cpu load etc.

 
Average of ratings: -
Picture of Chris Sequeira
Re: Timestamps in mdl_user and mdl_log don't match
 

Ah, good info, thanks; I understand the process better now.

I guess the few seconds delay might be the fact that my test 2.3.3 moodle is running on XAMPP on a laptop.

However, my 2.2.1 moodle is on a managed virtual server (dual Xeon, 4GB, CentOS, Apache, MySQL) with near-zero load (testing phase), and it too showed differences from a few seconds to several minutes! 

Anyway, I guess for consistency in reporting, it's better to rely on mdl_log exclusively, and ignore the access fields in mdl_user.

 
Average of ratings: -
Picture of Darko Miletić
Re: Timestamps in mdl_user and mdl_log don't match
Group DevelopersGroup Particularly helpful Moodlers

ah xampp.... I guess it is good for quick and dirty tests but it is still something that should be avoided. 

In general better performance results on windows can be obtained by using:

 
Average of ratings: -
Picture of Chris Sequeira
Re: Timestamps in mdl_user and mdl_log don't match
 

Then that's what my next "clean" install will be!

I'd always used individual rpms on linux, but never tried anything other than XAMPP on windows.

 
Average of ratings: -
Tim at Lone Pine Koala Sanctuary
Re: Timestamps in mdl_user and mdl_log don't match
Group DevelopersGroup Documentation writersGroup Particularly helpful Moodlers

If you only use mdl_log for running reports, you will find that over time it gets very slow, because mdl_log gets very big. That is why the user_last_access table was added in the first place.

The other thing to note is that the lastaccess table is not updated every single time the user requests a page. There is a constant LASTACCESS_UPDATE_SECS (equal to 60 seconds) and to improve performance, the last access information is only updated that frequently.

 
Average of ratings: -
Picture of Chris Sequeira
Re: Timestamps in mdl_user and mdl_log don't match
 

Oh, that's why last_access always lags by less than a minute. First_access, however, varies wildly. I remember seeing forum posts about that - I'll look it up.

For reporting, I'm going to use separate summary tables created - and progressively updated (2 to 6 times a day) - from mdl_log and related tables. These summary tables would store aggregated data specifically for a set of predefined reports. No *.* rogue db queries allowed evil

So only the latest unsummarized records from mdl_log (and cousins) would be processed a few times a day. 

I'd done this a while ago in m1.9. The reports didn't have right-now info, but a "Report data as on <timestamp>" caption was fine with the big brothers. And, for those who couldn't wait, a couple of adhoc-query-powered Certified/Not Yet Certified-type reports maintained a reasonable level of contentment...

 
Average of ratings: -