Hi,

we recently upgraded from 3.8 to 3.9.11 (20211223).

A course page of ours containing a lot of choice activities (hundreds of them) that used to take a few seconds to load, since the upgrade is unable to load due to the timeout (600 secs).

While processing the request on that page the load on the DB is quite normal, but we found out a php72-fpm taking a whole CPU all the 600 seconds long. So we straced it and observed a fast moving loop whose iterations are always the same:

access("/var/www/html/mod/choice/lib.php", F_OK) = 0
access("/var/www/html/mod/choice/lib.php", F_OK) = 0
access("/moodledata/cache/cachestore_file/default_application/core_coursemodinfo/432-cache/432-78dfb667b9e7212d729b7c511330f8d9.cache", F_OK) = 0
openat(AT_FDCWD, "/moodledata/cache/cachestore_file/default_application/core_coursemodinfo/432-cache/432-78dfb667b9e7212d729b7c511330f8d9.cache", O_RDONLY) = 7
fstat(7, {st_mode=S_IFREG|0666, st_size=109543, ...}) = 0
lseek(7, 0, SEEK_CUR)                   = 0
flock(7, LOCK_SH)                       = 0
read(7, "O:8:\"stdClass\":9:{s:7:\"modinfo\";"..., 8192) = 8192
read(7, "ectionid\";s:4:\"3713\";s:6:\"module"..., 8192) = 8192
read(7, ":7:\"section\";s:1:\"1\";s:9:\"sectio"..., 8192) = 8192
read(7, "lass\":11:{s:2:\"id\";s:3:\"143\";s:2"..., 8192) = 8192
read(7, "ded\";s:10:\"1446555327\";s:7:\"visi"..., 8192) = 8192
read(7, "le\";s:1:\"3\";s:5:\"added\";s:10:\"14"..., 8192) = 8192
read(7, "\";s:9:\"sectionid\";s:4:\"3713\";s:6"..., 8192) = 8192
read(7, "0\";s:19:\"visibleoncoursepage\";i:"..., 8192) = 8192
read(7, ":\"section\";s:1:\"1\";s:9:\"sectioni"..., 8192) = 8192
read(7, "19:\"visibleoncoursepage\";i:1;s:1"..., 8192) = 8192
read(7, "12:\"GIOVEDI' 3 settembre, 17:00-"..., 8192) = 8192
read(7, "\"0\";s:4:\"name\";s:83:\"VENERDI' 11"..., 8192) = 8192
read(7, ";s:10:\"visibleold\";s:1:\"0\";s:4:\""..., 8192) = 8192
read(7, " 69, 64);\"><span style=\"\"><span "..., 8192) = 3047
read(7, "", 8192)                       = 0
flock(7, LOCK_UN)                       = 0
close(7)                                = 0
sendto(5, "M\0\0\0\3SELECT * FROM mdl_context W"..., 81, MSG_DONTWAIT, NULL, 0) = 81
poll([\{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 86400000) = 1 ([\{fd=5, revents=POLLIN}])
recvfrom(5, "\1\0\0\1\0066\0\0\2\3def\6moodle\vmdl_context"..., 25963, MSG_DONTWAIT, NULL, NULL) = 459
sendto(5, "\267\0\0\0\3SELECT ctx.path, ra.roleid,"..., 187, MSG_DONTWAIT, NULL, 0) = 187
poll([\{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 86400000) = 1 ([\{fd=5, revents=POLLIN}])
recvfrom(5, "\1\0\0\1\0032\0\0\2\3def\6moodle\3ctx\vmdl_con"..., 25504, MSG_DONTWAIT, NULL, NULL) = 609
access("/var/www/html/mod/choice/lib.php", F_OK) = 0
access("/var/www/html/mod/choice/lib.php", F_OK) = 0

Any idea on what change in 3.9 may be the root cause?

What additional information do you need to address this problem?

Thank you

PL