mputzi
commented
3 years ago Even after killing the process of the adhoc task the mysqld process stays at 100% CPU load. Restarting mysqld recovers the database process.
Closed mputzi closed 1 year ago
mputzi
commented
3 years ago Even after killing the process of the adhoc task the mysqld process stays at 100% CPU load. Restarting mysqld recovers the database process.
justusdieckmann
commented
3 years ago Hey Martin,
are you using MySQL or MariaDB and which version are you using? I would be surprised if it is important, but what php version are you using?
Justus
roessling
commented
3 years ago In the same vein, I get this error (luckily, sent by email) when exporting data for a privacy inspection. I am running the weekly stable build of Moodle (currently, this is 3.10.3+ (Build: 20210330)) and the latest release of the plugin (v3.10-r1 - 2020111300), using PostgreSQL (11.11 under Debian) and PHP 7.3.27-1.
Beim Aufruf von mod_moodleoverflow\privacy\provider::get_contexts_for_userid ist ein Fehler aufgetreten. Das Plugin mod_moodleoverflow hat die Verarbeitung der Daten nicht beendet. Unten finden Sie Informationen für den Pluginentwickler.
Fehler beim Lesen der Datenbank
mputzi
commented
3 years ago Hey Martin,
are you using MySQL or MariaDB and which version are you using? I would be surprised if it is important, but what php version are you using?
Justus
We are using MariaDB: mysql Ver 15.1 Distrib 10.3.25-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
For moodle we use php7.4-fpm. php-Version: PHP 7.4.3 (cli) (built: Oct 6 2020 15:47:56) ( NTS ) Copyright (c) The PHP Group Zend Engine v3.4.0, Copyright (c) Zend Technologies with Zend OPcache v7.4.3, Copyright (c), by Zend Technologies
justusdieckmann
commented
3 years ago Thank you both for your information. Sadly, I couldn't reproduce the problem. Could you (temporarily) replace Lines 182 and 183 in mod/moodleoverflow/classes/privacy/provider.php with the code below, create a new data request, run the adhoc task and post the new log? It should then contain details about the database error.
global $DB;
$DB->set_debug(true);
try {
$contextlist = new \core_privacy\local\request\contextlist();
$contextlist->add_from_sql($sql, $params);
} finally {
$DB->set_debug(false);
}Hi, I did that, but still get exactly the same mail as above. The most relevant part seems to be this line: Beim Aufruf von mod_moodleoverflow\privacy\provider::get_contexts_for_userid ist ein Fehler aufgetreten. Das Plugin mod_moodleoverflow konnte die Verarbeitung der Daten nicht beenden. Folgende Informationen könnten den Entwickler/innen helfen:
Fehler beim Lesen der Datenbank
justusdieckmann
commented
3 years ago Hi @roessling
Yes, I think so too, that's why I try to get more information about the database access in get_contexts_for_userid. Could you look into the complete adhoc log (via Settings > Server > Tasks > Task logs ) for that specific task execution and see if there is some debug output in there? (I assume the email only contains the exception, and not the complete log, right?).
mputzi
commented
3 years ago Thank you both for your information. Sadly, I couldn't reproduce the problem. Could you (temporarily) replace Lines 182 and 183 in
mod/moodleoverflow/classes/privacy/provider.phpwith the code below, create a new data request, run the adhoc task and post the new log? It should then contain details about the database error.global $DB; $DB->set_debug(true); try { $contextlist = new \core_privacy\local\request\contextlist(); $contextlist->add_from_sql($sql, $params); } finally { $DB->set_debug(false); }
Okay, I changed the lines as you said. This is the result:
/var/www/moodle/admin/cli$ sudo -u www-data php adhoc_task.php -e -i -f
Server Time: Thu, 08 Apr 2021 13:54:45 +0200
Execute adhoc task: tool_dataprivacy\task\process_data_request_task
... started 13:54:45. Current memory use 12.9MB.
Pre-processing request...
Laden von 550 Komponenten (Donnerstag, 8. April 2021, 13:54)
antivirus_clamav wird verarbeitet (1/550) (Donnerstag, 8. April 2021, 13:54)
availability_completion wird verarbeitet (2/550) (Donnerstag, 8. April 2021, 13:54)
availability_date wird verarbeitet (3/550) (Donnerstag, 8. April 2021, 13:54)
availability_grade wird verarbeitet (4/550) (Donnerstag, 8. April 2021, 13:54)
availability_group wird verarbeitet (5/550) (Donnerstag, 8. April 2021, 13:54)
availability_grouping wird verarbeitet (6/550) (Donnerstag, 8. April 2021, 13:54)
availability_profile wird verarbeitet (7/550) (Donnerstag, 8. April 2021, 13:54)
availability_xp wird verarbeitet (8/550) (Donnerstag, 8. April 2021, 13:54)
qtype_algebra wird verarbeitet (9/550) (Donnerstag, 8. April 2021, 13:54)
qtype_calculated wird verarbeitet (10/550) (Donnerstag, 8. April 2021, 13:54)
qtype_calculatedmulti wird verarbeitet (11/550) (Donnerstag, 8. April 2021, 13:54)
qtype_calculatedsimple wird verarbeitet (12/550) (Donnerstag, 8. April 2021, 13:54)
qtype_ddimageortext wird verarbeitet (13/550) (Donnerstag, 8. April 2021, 13:54)
qtype_ddmarker wird verarbeitet (14/550) (Donnerstag, 8. April 2021, 13:54)
qtype_ddmatch wird verarbeitet (15/550) (Donnerstag, 8. April 2021, 13:54)
qtype_ddwtos wird verarbeitet (16/550) (Donnerstag, 8. April 2021, 13:54)
qtype_description wird verarbeitet (17/550) (Donnerstag, 8. April 2021, 13:54)
qtype_essay wird verarbeitet (18/550) (Donnerstag, 8. April 2021, 13:54)
qtype_formulas wird verarbeitet (19/550) (Donnerstag, 8. April 2021, 13:54)
qtype_gapfill wird verarbeitet (20/550) (Donnerstag, 8. April 2021, 13:54)
qtype_gapselect wird verarbeitet (21/550) (Donnerstag, 8. April 2021, 13:54)
qtype_geogebra wird verarbeitet (22/550) (Donnerstag, 8. April 2021, 13:54)
qtype_match wird verarbeitet (23/550) (Donnerstag, 8. April 2021, 13:54)
qtype_matrix wird verarbeitet (24/550) (Donnerstag, 8. April 2021, 13:54)
qtype_missingtype wird verarbeitet (25/550) (Donnerstag, 8. April 2021, 13:54)
qtype_multianswer wird verarbeitet (26/550) (Donnerstag, 8. April 2021, 13:54)
qtype_multichoice wird verarbeitet (27/550) (Donnerstag, 8. April 2021, 13:54)
qtype_numerical wird verarbeitet (28/550) (Donnerstag, 8. April 2021, 13:54)
qtype_random wird verarbeitet (29/550) (Donnerstag, 8. April 2021, 13:54)
qtype_randomsamatch wird verarbeitet (30/550) (Donnerstag, 8. April 2021, 13:54)
qtype_shortanswer wird verarbeitet (31/550) (Donnerstag, 8. April 2021, 13:54)
qtype_truefalse wird verarbeitet (32/550) (Donnerstag, 8. April 2021, 13:54)
qtype_wordselect wird verarbeitet (33/550) (Donnerstag, 8. April 2021, 13:54)
mod_assign wird verarbeitet (34/550) (Donnerstag, 8. April 2021, 13:54)
mod_assignment wird verarbeitet (35/550) (Donnerstag, 8. April 2021, 13:54)
mod_attendance wird verarbeitet (36/550) (Donnerstag, 8. April 2021, 13:54)
mod_bigbluebuttonbn wird verarbeitet (37/550) (Donnerstag, 8. April 2021, 13:54)
mod_book wird verarbeitet (38/550) (Donnerstag, 8. April 2021, 13:54)
mod_chat wird verarbeitet (39/550) (Donnerstag, 8. April 2021, 13:54)
mod_checklist wird verarbeitet (40/550) (Donnerstag, 8. April 2021, 13:54)
mod_choice wird verarbeitet (41/550) (Donnerstag, 8. April 2021, 13:54)
mod_data wird verarbeitet (42/550) (Donnerstag, 8. April 2021, 13:54)
mod_debate wird verarbeitet (43/550) (Donnerstag, 8. April 2021, 13:54)
mod_evoting wird verarbeitet (44/550) (Donnerstag, 8. April 2021, 13:54)
mod_feedback wird verarbeitet (45/550) (Donnerstag, 8. April 2021, 13:54)
mod_folder wird verarbeitet (46/550) (Donnerstag, 8. April 2021, 13:54)
mod_forum wird verarbeitet (47/550) (Donnerstag, 8. April 2021, 13:54)
mod_game wird verarbeitet (48/550) (Donnerstag, 8. April 2021, 13:54)
mod_glossary wird verarbeitet (49/550) (Donnerstag, 8. April 2021, 13:54)
mod_groupmembers wird verarbeitet (50/550) (Donnerstag, 8. April 2021, 13:54)
mod_h5pactivity wird verarbeitet (51/550) (Donnerstag, 8. April 2021, 13:54)
mod_hotquestion wird verarbeitet (52/550) (Donnerstag, 8. April 2021, 13:54)
mod_hvp wird verarbeitet (53/550) (Donnerstag, 8. April 2021, 13:54)
mod_imscp wird verarbeitet (54/550) (Donnerstag, 8. April 2021, 13:54)
mod_jitsi wird verarbeitet (55/550) (Donnerstag, 8. April 2021, 13:54)
mod_label wird verarbeitet (56/550) (Donnerstag, 8. April 2021, 13:54)
mod_lesson wird verarbeitet (57/550) (Donnerstag, 8. April 2021, 13:54)
mod_lti wird verarbeitet (58/550) (Donnerstag, 8. April 2021, 13:54)
mod_moodleoverflow wird verarbeitet (59/550) (Donnerstag, 8. April 2021, 13:54)
--------------------------------
SELECT ctx.id AS ctxid, ctx.path AS ctxpath, ctx.depth AS ctxdepth, ctx.contextlevel AS ctxlevel, ctx.instanceid AS ctxinstance, ctx.locked AS ctxlocked
FROM mdl_context ctx
JOIN (SELECT c.id
FROM mdl_context c
INNER JOIN mdl_course_modules cm ON cm.id = c.instanceid AND c.contextlevel = ?
INNER JOIN mdl_modules m ON m.id = cm.module AND m.name = ?
INNER JOIN mdl_moodleoverflow mof ON mof.id = cm.instance
LEFT JOIN mdl_moodleoverflow_discussions d ON d.moodleoverflow = mof.id
LEFT JOIN mdl_moodleoverflow_posts p ON p.discussion = d.id
LEFT JOIN mdl_moodleoverflow_read r ON r.moodleoverflowid = mof.id
LEFT JOIN mdl_moodleoverflow_subscriptions s ON s.moodleoverflow = mof.id
LEFT JOIN mdl_moodleoverflow_discuss_subs ds ON ds.moodleoverflow = mof.id
LEFT JOIN mdl_moodleoverflow_ratings ra ON ra.moodleoverflowid = mof.id
LEFT JOIN mdl_moodleoverflow_tracking track ON track.moodleoverflowid = mof.id
LEFT JOIN mdl_moodleoverflow_grades g ON g.moodleoverflowid = mof.id
WHERE (
d.userid = ? OR
d.usermodified = ? OR
p.userid = ? OR
r.userid = ? OR
s.userid = ? OR
ds.userid = ? OR
ra.userid = ? OR
track.userid = ? OR
g.userid = ?
)
) target ON ctx.id = target.id
[array (
0 => 70,
1 => 'moodleoverflow',
2 => 411,
3 => 411,
4 => 411,
5 => 411,
6 => 411,
7 => 411,
8 => 411,
9 => 411,
10 => 411,
)]
--------------------------------The request is indeed from the user with ID 411.
justusdieckmann
commented
3 years ago Thanks @mputzi , and sorry for the delay. I still wasn't able to reproduce the bug. @roessling Do you still encounter the problem? If so, could you look at https://github.com/learnweb/moodle-mod_moodleoverflow/issues/75#issuecomment-815625562? Your output might contain more information, since it seems that postgres actually responds, instead of locking up like mariadb.
roessling
commented
3 years ago I think the problem will only occur if the person who requests the information who has also written something in a moodleoverflow. As these are used only very sparingly in my Moodle instance (and we only get a negligible number of privacy requests), the problem has not reappeared - but that does not necessarily mean it's "gone". I also made the requests change (and the DB continues to run), but there was no further output than the one above.
When I run the query from above manually (inserting all values into the placeholders, and running it via "Moodle Adminer"), I get "No rows" (which may be correct, see above), but no error.
NinaHerrmann
commented
1 year ago @justusdieckmann did you checked with a person writing a post? If that is the case, I suppose we are not really able to reproduce the error.
geichelberger
commented
1 year ago We encountered the same error, and the same SQL query seemed involved. We try to together more data.
moodle 3.11.13 moodleoverflow v4.1-r1
ziegenberg
commented
1 year ago The query runs for a very long time. Obtaining the query execution plan gives the following answer. Looks expensive.
EXPLAIN: -> Filter: ((d.userid = 92701) or (d.usermodified = 92701) or (p.userid = 92701) or (r.userid = 92701) or (s.userid = 92701) or (ds.userid = 92701) or (ra.userid = 92701) or (track.userid = 92701) or (g.userid = 92701)) (cost=89138417259074.34 rows=885770895536109)
-> Left hash join (g.moodleoverflowid = mof.id) (cost=89138417259074.34 rows=885770895536109)
-> Left hash join (track.moodleoverflowid = mof.id) (cost=44311163039719.12 rows=442885447768055)
-> Left hash join (ra.moodleoverflowid = mof.id) (cost=452056420016.56 rows=4519239262939)
-> Nested loop left join (cost=729920271.62 rows=3352551382)
-> Nested loop left join (cost=32589595.21 rows=160922461)
-> Left hash join (r.moodleoverflowid = mof.id) (cost=109318.51 rows=1092535)
-> Nested loop left join (cost=319.92 rows=240)
-> Nested loop left join (cost=91.90 rows=80)
-> Nested loop inner join (cost=63.94 rows=4)
-> Nested loop inner join (cost=62.54 rows=4)
-> Nested loop inner join (cost=61.15 rows=4)
-> Inner hash join (no condition) (cost=10.85 rows=75)
-> Index scan on mof using mdl_mood_cou_ix (cost=10.50 rows=75)
-> Hash
-> Covering index lookup on m using mdl_modu_nam_ix (name='moodleoverflow') (cost=0.35 rows=1)
-> Filter: (cm.module = m.id) (cost=0.48 rows=0.05)
-> Index lookup on cm using mdl_courmodu_ins_ix (instance=mof.id) (cost=0.48 rows=2)
-> Filter: (c.contextlevel = 70) (cost=0.28 rows=1)
-> Single-row covering index lookup on c using mdl_cont_conins_uix (contextlevel=70, instanceid=cm.id) (cost=0.28 rows=1)
-> Single-row index lookup on ctx using PRIMARY (id=c.id) (cost=0.28 rows=1)
-> Index lookup on d using mdl_mooddisc_moo_ix (moodleoverflow=mof.id) (cost=5.51 rows=20)
-> Index lookup on p using mdl_moodpost_dis_ix (discussion=d.id) (cost=2.56 rows=3)
-> Hash
-> Index scan on r using mdl_moodread_usemoo_ix (cost=2.16 rows=4554)
-> Index lookup on s using mdl_moodsubs_moo_ix (moodleoverflow=mof.id) (cost=15.00 rows=147)
-> Index lookup on ds using mdl_mooddiscsubs_moo_ix (moodleoverflow=mof.id) (cost=2.25 rows=21)
-> Hash
-> Index scan on ra using mdl_moodrati_usemoo_ix (cost=0.04 rows=1348)
-> Hash
-> Index scan on track using mdl_moodtrac_usemoo_ix (cost=0.01 rows=98)
-> Hash
-> Table scan on g (cost=0.00 rows=2)Sounds reasonable, does anybody has resources to optimize the query?
NinaHerrmann
commented
1 year ago ah is SpaceCafe related to you?
geichelberger
commented
1 year ago No :)
SpaceCafe
commented
1 year ago We had this issue a "long" time ago (~1y) and used this fix in production
ziegenberg
commented
1 year ago The fix is faster, but it's still taking more than 8 minutes to return an empty set.
mysql> SELECT c.id
-> FROM mdl_context c
-> INNER JOIN mdl_course_modules cm ON cm.id = c.instanceid AND c.contextlevel = '70'
-> INNER JOIN mdl_modules m ON m.id = cm.module AND m.name = 'moodleoverflow'
-> INNER JOIN mdl_moodleoverflow mof ON mof.id = cm.instance
-> LEFT JOIN mdl_moodleoverflow_discussions d ON d.moodleoverflow = mof.id
-> LEFT JOIN mdl_moodleoverflow_posts p ON p.discussion = d.id
-> LEFT JOIN mdl_moodleoverflow_read r ON r.moodleoverflowid = mof.id
-> LEFT JOIN mdl_moodleoverflow_subscriptions s ON s.moodleoverflow = mof.id
-> WHERE (
-> d.userid = '92701' OR
-> d.usermodified = '92701' OR
-> p.userid = '92701' OR
-> r.userid = '92701' OR
-> s.userid = '92701'
-> ) GROUP BY c.id;
Empty set (8 min 35.43 sec)How about the following query?
SELECT c.id
FROM mdl_context c
INNER JOIN mdl_course_modules cm ON cm.id = c.instanceid AND c.contextlevel = '70'
INNER JOIN mdl_modules m ON m.id = cm.module AND m.name = 'moodleoverflow'
INNER JOIN mdl_moodleoverflow mof ON mof.id = cm.instance
WHERE EXISTS (
SELECT 1 FROM mdl_moodleoverflow_discussions d WHERE d.moodleoverflow = mof.id AND (d.userid = '25778' OR d.usermodified = '25778')
) OR EXISTS (
SELECT 1 FROM mdl_moodleoverflow_posts p WHERE p.discussion IN (SELECT id FROM mdl_moodleoverflow_discussions WHERE moodleoverflow = mof.id) AND p.userid = '25778'
) OR EXISTS (
SELECT 1 FROM mdl_moodleoverflow_read r WHERE r.moodleoverflowid = mof.id AND r.userid = '25778'
) OR EXISTS (
SELECT 1 FROM mdl_moodleoverflow_subscriptions s WHERE s.moodleoverflow = mof.id AND s.userid = '25778'
) OR EXISTS (
SELECT 1 FROM mdl_moodleoverflow_discuss_subs ds WHERE ds.moodleoverflow = mof.id AND ds.userid = '25778'
) OR EXISTS (
SELECT 1 FROM mdl_moodleoverflow_ratings ra WHERE ra.moodleoverflowid = mof.id AND ra.userid = '25778'
) OR EXISTS (
SELECT 1 FROM mdl_moodleoverflow_tracking track WHERE track.moodleoverflowid = mof.id AND track.userid = '25778'
) OR EXISTS (
SELECT 1 FROM mdl_moodleoverflow_grades g WHERE g.moodleoverflowid = mof.id AND g.userid = '25778'
);EXPLAIN looks a lot better:
EXPLAIN: -> Nested loop inner join (cost=62.54 rows=4)
-> Nested loop inner join (cost=61.15 rows=4)
-> Filter: (exists(select #2) or exists(select #3) or exists(select #5) or exists(select #6) or exists(select #7) or exists(select #8) or exists(select #9) or exists(select #10)) (cost=10.85 rows=75)
-> Inner hash join (no condition) (cost=10.85 rows=75)
-> Index scan on mof using mdl_mood_cou_ix (cost=10.50 rows=75)
-> Hash
-> Covering index lookup on m using mdl_modu_nam_ix (name='moodleoverflow') (cost=0.35 rows=1)
-> Select #2 (subquery in condition; dependent)
-> Limit: 1 row(s) (cost=5.21 rows=1)
-> Filter: ((d.userid = 25778) or (d.usermodified = 25778)) (cost=5.21 rows=2)
-> Index lookup on d using mdl_mooddisc_moo_ix (moodleoverflow=mof.id) (cost=5.21 rows=20)
-> Select #3 (subquery in condition; dependent)
-> Limit: 1 row(s) (cost=59.39 rows=1)
-> Nested loop inner join (cost=59.39 rows=2)
-> Covering index lookup on mdl_moodleoverflow_discussions using mdl_mooddisc_moo_ix (moodleoverflow=mof.id) (cost=2.26 rows=20)
-> Filter: (p.userid = 25778) (cost=2.55 rows=0.1)
-> Index lookup on p using mdl_moodpost_dis_ix (discussion=mdl_moodleoverflow_discussions.id) (cost=2.55 rows=3)
-> Select #5 (subquery in condition; dependent)
-> Limit: 1 row(s) (cost=0.37 rows=0.1)
-> Filter: ((r.userid = 25778) and (r.moodleoverflowid = mof.id)) (cost=0.37 rows=0.1)
-> Covering index range scan on r using mdl_moodread_usemoo_ix over (userid = 25778) (cost=0.37 rows=1)
-> Select #6 (subquery in condition; dependent)
-> Limit: 1 row(s) (cost=0.52 rows=0.2)
-> Filter: (s.moodleoverflow = mof.id) (cost=0.52 rows=0.2)
-> Index lookup on s using mdl_moodsubs_use_ix (userid=25778), with index condition: (s.userid = 25778) (cost=0.52 rows=2)
-> Select #7 (subquery in condition; dependent)
-> Limit: 1 row(s) (cost=0.26 rows=0.1)
-> Filter: (ds.moodleoverflow = mof.id) (cost=0.26 rows=0.1)
-> Index lookup on ds using mdl_mooddiscsubs_usedis_uix (userid=25778), with index condition: (ds.userid = 25778) (cost=0.26 rows=1)
-> Select #8 (subquery in condition; dependent)
-> Limit: 1 row(s) (cost=0.61 rows=1)
-> Filter: (ra.userid = 25778) (cost=0.61 rows=4)
-> Covering index lookup on ra using mdl_moodrati_usemoo_ix (userid=25778, moodleoverflowid=mof.id) (cost=0.61 rows=4)
-> Select #9 (subquery in condition; dependent)
-> Limit: 1 row(s) (cost=0.35 rows=1)
-> Filter: (track.userid = 25778) (cost=0.35 rows=1)
-> Covering index lookup on track using mdl_moodtrac_usemoo_ix (userid=25778, moodleoverflowid=mof.id) (cost=0.35 rows=1)
-> Select #10 (subquery in condition; dependent)
-> Limit: 1 row(s) (cost=0.45 rows=1)
-> Filter: ((g.userid = 25778) and (g.moodleoverflowid = mof.id)) (cost=0.45 rows=1)
-> Table scan on g (cost=0.45 rows=2)
-> Filter: (cm.module = m.id) (cost=0.48 rows=0.05)
-> Index lookup on cm using mdl_courmodu_ins_ix (instance=mof.id) (cost=0.48 rows=2)
-> Filter: (c.contextlevel = 70) (cost=0.28 rows=1)And the execution time is down to milliseconds.
moodle 3.10.3+ moodleoverflow v3.10-r1 (2020111300)
Steps to reproduce:
AdHoc-Task \tool_dataprivacy\task\process_data_request_task started (and replicated to number of max allowed concurrent AdHoc-Tasks). Tasks fails at moodleoverflow-plugin -> mysqld-process at 100% CPU (3 times) -> server is slowed down
There is no way of stopping or deleting this adhoc-Task from graphical moodle interface.
output when starting via cli:
nothing more. The process is not finishing and is not being terminated or killed automatically after max execution time for AdHoc-Tasks.
Please help.
Regards, Martin.