cron très long

cron très long

par Laurent Labidi,
Nombre de réponses : 9

Bonjour à tous,

Pourriez-vous m'indiquer pourquoi mon cron est si long ? avant il était de moins de 10 secondes...

Server Time: Thu, 06 Oct 2016 23:53:14 +0200


Execute scheduled task: Nettoyage des anciennes sessions (core\task\session_cleanup_task)
... started 23:53:24. Current memory use 5.7Mo.
... used 8 dbqueries
... used 0.029516935348511 seconds
Scheduled task complete: Nettoyage des anciennes sessions (core\task\session_cleanup_task)
Execute scheduled task: Envoi des nouveaux mots de passe (core\task\send_new_user_passwords_task)
... started 23:53:34. Current memory use 6.4Mo.
... used 1 dbqueries
... used 0.0012109279632568 seconds
Scheduled task complete: Envoi des nouveaux mots de passe (core\task\send_new_user_passwords_task)
Execute scheduled task: Envoi des notifications d'échec de connexion (core\task\send_failed_login_notifications_task)
... started 23:53:44. Current memory use 6.4Mo.
... used 2 dbqueries
... used 0.001021146774292 seconds
Scheduled task complete: Envoi des notifications d'échec de connexion (core\task\send_failed_login_notifications_task)
Execute scheduled task: Traitement du cron des plugins obsolètes (core\task\legacy_plugin_cron_task)
... started 23:53:54. Current memory use 6.4Mo.
Running auth crons if required...
Running enrol crons if required...
Starting activity modules
Processing module function assign_cron ...
... used 4 dbqueries
... used 0.14574980735779 seconds
done.
Processing module function quiz_cron ...

  Looking for quiz overdue quiz attempts...
  Considered 0 attempts in 0 quizzes.
Starting quiz reports
Finished quiz reports
... used 2 dbqueries
... used 0.075104951858521 seconds
done.
Processing module function workshop_cron ...
 processing workshop subplugins ...
Starting workshop allocation methods
Processing cron function for workshopallocation_scheduled...
... started 23:53:54. Current memory use 9.4Mo.
... no workshops awaiting scheduled allocation. done. (1 dbqueries, 0 seconds)
Finished workshop allocation methods
... used 6 dbqueries
... used 0.031867980957031 seconds
done.
Processing module function checklist_cron ...
... used 1 dbqueries
... used 0.0024831295013428 seconds
done.
Finished activity modules
Starting blocks
Processing cron function for recent_activity....done.
Finished blocks
Starting admin reports
Finished admin reports
Starting course reports
Finished course reports
Starting gradebook plugins
Finished gradebook plugins
Starting repository plugins
Processing cron function for repository_dropbox...
... started 23:53:54. Current memory use 9.8Mo.
done. (1 dbqueries, 0 seconds)
Processing cron function for repository_filesystem...
... started 23:53:54. Current memory use 9.8Mo.
done. (3 dbqueries, 0 seconds)
Finished repository plugins
... used 26 dbqueries
... used 0.38336610794067 seconds
Scheduled task complete: Traitement du cron des plugins obsolètes (core\task\legacy_plugin_cron_task)
Execute scheduled task: Traitement en tâche de fond du carnet de notes (core\task\grade_cron_task)
... started 23:54:04. Current memory use 9.8Mo.
    Deleted old grade history records from 'grade_outcomes_history'
    Deleted old grade history records from 'grade_categories_history'
    Deleted old grade history records from 'grade_items_history'
    Deleted old grade history records from 'grade_grades_history'
    Deleted old grade history records from 'scale_history'
... used 7 dbqueries
... used 0.0070500373840332 seconds
Scheduled task complete: Traitement en tâche de fond du carnet de notes (core\task\grade_cron_task)
Execute scheduled task: Traitement en tâche de fond des événements (core\task\events_cron_task)
... started 23:54:14. Current memory use 9.9Mo.
... used 2 dbqueries
... used 0.00054001808166504 seconds
Scheduled task complete: Traitement en tâche de fond des événements (core\task\events_cron_task)
Execute scheduled task: Traitement en tâche de fond des plugins de portfolio (core\task\portfolio_cron_task)
... started 23:54:24. Current memory use 9.9Mo.
... used 0 dbqueries
... used 7.6055526733398E-5 seconds
Scheduled task complete: Traitement en tâche de fond des plugins de portfolio (core\task\portfolio_cron_task)
Execute scheduled task: Traitement en tâche de fond des cron obsolètes des plugins de détection de plagiat (core\task\plagiarism_cron_task)
... started 23:54:34. Current memory use 9.9Mo.
... used 0 dbqueries
... used 0.001143217086792 seconds
Scheduled task complete: Traitement en tâche de fond des cron obsolètes des plugins de détection de plagiat (core\task\plagiarism_cron_task)
Execute scheduled task: Traitement en tâche de fond du moteur de questions (core\task\question_cron_task)
... started 23:54:44. Current memory use 9.9Mo.

  Cleaning up old question previews...done.

  Cleaning up old question statistics cache records...done.
... used 6 dbqueries
... used 0.0054659843444824 seconds
Scheduled task complete: Traitement en tâche de fond du moteur de questions (core\task\question_cron_task)
Execute scheduled task: Calcul des données d'achèvement (core\task\completion_regular_task)
... started 23:54:54. Current memory use 10Mo.
... used 6 dbqueries
... used 0.060436964035034 seconds
Scheduled task complete: Calcul des données d'achèvement (core\task\completion_regular_task)
Execute scheduled task: Suppression des événements surveillés superflus (tool_monitor\task\clean_events)
... started 23:55:04. Current memory use 9.4Mo.
... used 0 dbqueries
... used 0.00026702880859375 seconds
Scheduled task complete: Suppression des événements surveillés superflus (tool_monitor\task\clean_events)
Execute scheduled task: Envoi des messages et maintenance des forums (mod_forum\task\cron_task)
... started 23:55:14. Current memory use 10.6Mo.
Starting digest processing...
Cleaned old digest records
... used 5 dbqueries
... used 0.02027702331543 seconds
Scheduled task complete: Envoi des messages et maintenance des forums (mod_forum\task\cron_task)
Execute scheduled task: Récolte des courriels entrant (tool_messageinbound\task\pickup_task)
... started 23:55:24. Current memory use 11.6Mo.
Inbound Message not fully configured - exiting early.
... used 0 dbqueries
... used 0.004612922668457 seconds
Scheduled task complete: Récolte des courriels entrant (tool_messageinbound\task\pickup_task)
Cron script completed correctly
Cron completed at 23:55:34. Memory used 11.6Mo.
Execution took 139.821456 seconds
merci d'avance !
Moyenne des évaluations  -
En réponse à Laurent Labidi

Re: cron très long

par Nicolas Martignoni,
Avatar Développeurs Avatar Développeurs de plugins Avatar Documentation writers Avatar Moodleurs particulièrement utiles Avatar Testeurs Avatar Traducteurs

Bonjour,

Difficile de vous aider sans plus d'info.

> avant il était de moins de 10 secondes...

Que signifie « avant » ? Ancienne version de Moodle ? Si vous avez mis à jour Moodle, avez-vous tenu compte du changement de fonctionnement du cron ?

À quelle fréquence lancez-vous le cron ?

En réponse à Nicolas Martignoni

Re: cron très long

par Patrick Lemaire,
Avatar Développeurs de plugins Avatar Documentation writers Avatar Moodleurs particulièrement utiles Avatar Testeurs Avatar Traducteurs

Bonjour,

A titre d'indication, pour un Moodle version 3.1.1, avec une moyenne de +6000 visites par jour, 4500 espaces de cours, le CRON qui tourne tous les 5 minutes (oui, normalement la recommandation est de le lancer toutes les minutes...) prend 30 secondes. Et encore, ça dépend beaucoup de l'activité du moment. Par exemple, lorsque j'ai lancé le CRON, j'ai pris soin d'attendre que le dernier soit bien terminé, je l'ai lancé manuellement 1 minutes avant le suivant et dedans, il y avait des notifications d'un forum particulièrement suivi clin d’œil

A suivre...
Patrick

En réponse à Patrick Lemaire

Re: cron très long

par Laurent Labidi,

Merci pour vos réponses !

Quelques précisions donc:

Moddle 3.1.2+ installé sur un serveur linux sous Centos 6 + couche plesk

Cette version actuelle est la mise à jour d'anciens moodle (1.9 > 2.7 > 2.9 > 3.0 > 3.1 > 3.1.2)

Passage d'anatole à baracuda effectué sur ma base

Cron lancé dans un premier temps toutes les seconde comme préconnisé...puis voyant qu'il prenait bien plus de temps en le lançant manuellement, je suis passé à tous les 5 min (*/5****)

Le cron lors du passage en 3.1 était très rapide (moins d'une seconde)...puis j'ai mis rajouter / enlever des plugins, des thèmes, des nouveaux cours, inscirt ma 50aine d'utiliseurs...Et des messages d'erreur ont commencé à arriver quotidiennement  de mon serveur (dans l'ordre de leur apparition)

"Cron daemon - sh: /usr/bin : ceci est un répertoire"

"PHP Notice:  Failed to load task: \mod_subcourse\task\fetch_grades* line 270 of /lib/classes/task/manager.php: call to debugging()
* line 477 of /lib/classes/task/manager.php: call to core\task\manager::scheduled_task_from_record()
* line 66 of /lib/cronlib.php: call to core\task\manager::get_next_scheduled_task()
* line 61 of /admin/cli/cron.php: call to cron_run()
 in /var/www/vhosts/foad.swimmingpole.fr/moodle/lib/weblib.php on line 3046"

"Default exception handler: L'opération s'est interrompue dans l'attente d'un verrouillage. Debug:
Error code: locktimeout
* line 461 of /lib/classes/task/manager.php: moodle_exception thrown
* line 66 of /lib/cronlib.php: call to core\task\manager::get_next_scheduled_task()
* line 61 of /admin/cli/cron.php: call to cron_run()"

Mon soucis est que je ne suis pas un informaticien et que je ne comprends ces lignes de code...si pour chaque message, vous aviez la traduction, je suis preneur sourire

J'imaginais que à la lecture du cron, on pourrait détecter ce qui prend du temps pour le modifier ou le désactiver dans les tâches planifiées depuis la dernière version...car effectiviment je n'ai rien fait de particulier pour adapter le cron lors des passages de version.

Encore merci de prendre le temps d'étudier mon problème !


En réponse à Laurent Labidi

Re: cron très long

par Séverin Terrier,
Avatar Documentation writers Avatar Moodleurs particulièrement utiles Avatar Testeurs Avatar Traducteurs

Bonjour,

Concernant tes différents messages d'erreur, est-ce que tu les as toujours tous (maintenant) ?

La ligne complète de lancement du cron serait éventuellement utile pour mieux comprendre les choses. Tu ne l'a pas modifiée du tout ?

En voyant le message parlant de mod_subcourse, je suppose que tu utilises ce module non standard. Peut-être qu'un souci vient de là...

Séverin

En réponse à Séverin Terrier

Re: cron très long

par Laurent Labidi,

Merci Séverin pour ta réponse.

Effectivement, le module sub_course avait été mal désinstallé...je l'ai réinstallé, lancé le cron, puis désinstallé proprement. Les messages le concernant ne sont plus présents maintenant. Plus aucun message d'erreur mais toujours plus de 130 secondes, malgré que les process accumulés ne fasse pas ce temps...ce qui est surprenant est qu'il y ait un temps de plusieurs secondes supplémentaires entre chaque tache lancée, et je ne sais pas comment le réduire (16h03m03s tache se lance et prend 0.14 sec, puis il faut attendre 16h34m23s pour que la suivante se lance, soit 20 sec entre les deux ??

"

Server Time: Thu, 13 Oct 2016 16:33:33 +0200


Execute scheduled task: Traitement en tâche de fond des événements (core\task\events_cron_task)
... started 16:33:43. Current memory use 5.7Mo.
... used 2 dbqueries
... used 0.015481948852539 seconds
Scheduled task complete: Traitement en tâche de fond des événements (core\task\events_cron_task)
Execute scheduled task: Traitement en tâche de fond des cron obsolètes des plugins de détection de plagiat (core\task\plagiarism_cron_task)
... started 16:33:53. Current memory use 6.4Mo.
... used 0 dbqueries
... used 0.0011730194091797 seconds
Scheduled task complete: Traitement en tâche de fond des cron obsolètes des plugins de détection de plagiat (core\task\plagiarism_cron_task)
Execute scheduled task: Traitement en tâche de fond du moteur de questions (core\task\question_cron_task)
... started 16:34:03. Current memory use 6.4Mo.

  Cleaning up old question previews...done.

  Cleaning up old question statistics cache records...done.
... used 6 dbqueries
... used 0.14172792434692 seconds
Scheduled task complete: Traitement en tâche de fond du moteur de questions (core\task\question_cron_task)
Execute scheduled task: Calcul des données d'achèvement (core\task\completion_regular_task)
... started 16:34:13. Current memory use 7.8Mo.
... used 6 dbqueries
... used 0.11913514137268 seconds
Scheduled task complete: Calcul des données d'achèvement (core\task\completion_regular_task)
Execute scheduled task: Suppression des événements surveillés superflus (tool_monitor\task\clean_events)
... started 16:34:23. Current memory use 7.6Mo.
... used 0 dbqueries
... used 0.00017189979553223 seconds
Scheduled task complete: Suppression des événements surveillés superflus (tool_monitor\task\clean_events)
Execute scheduled task: Envoi des messages et maintenance des forums (mod_forum\task\cron_task)
... started 16:34:33. Current memory use 8.8Mo.
Starting digest processing...
Cleaned old digest records
... used 5 dbqueries
... used 0.10403394699097 seconds
Scheduled task complete: Envoi des messages et maintenance des forums (mod_forum\task\cron_task)
Execute scheduled task: Récolte des courriels entrant (tool_messageinbound\task\pickup_task)
... started 16:34:43. Current memory use 9.8Mo.
Inbound Message not fully configured - exiting early.
... used 0 dbqueries
... used 0.0061299800872803 seconds
Scheduled task complete: Récolte des courriels entrant (tool_messageinbound\task\pickup_task)
Execute scheduled task: Nettoyage des anciennes sessions (core\task\session_cleanup_task)
... started 16:34:53. Current memory use 10.1Mo.
... used 9 dbqueries
... used 0.026445150375366 seconds
Scheduled task complete: Nettoyage des anciennes sessions (core\task\session_cleanup_task)
Execute scheduled task: Envoi des nouveaux mots de passe (core\task\send_new_user_passwords_task)
... started 16:35:03. Current memory use 10.2Mo.
... used 1 dbqueries
... used 0.001244068145752 seconds
Scheduled task complete: Envoi des nouveaux mots de passe (core\task\send_new_user_passwords_task)
Execute scheduled task: Envoi des notifications d'échec de connexion (core\task\send_failed_login_notifications_task)
... started 16:35:13. Current memory use 10.2Mo.
... used 2 dbqueries
... used 0.0011241436004639 seconds
Scheduled task complete: Envoi des notifications d'échec de connexion (core\task\send_failed_login_notifications_task)
Execute scheduled task: Traitement du cron des plugins obsolètes (core\task\legacy_plugin_cron_task)
... started 16:35:23. Current memory use 10.3Mo.
Running auth crons if required...
Running enrol crons if required...
Starting activity modules
Processing module function assign_cron ...
... used 4 dbqueries
... used 0.11381816864014 seconds
done.
Processing module function quiz_cron ...

  Looking for quiz overdue quiz attempts...
  Considered 0 attempts in 0 quizzes.
Starting quiz reports
Finished quiz reports
... used 2 dbqueries
... used 0.032895088195801 seconds
done.
Processing module function workshop_cron ...
 processing workshop subplugins ...
Starting workshop allocation methods
Processing cron function for workshopallocation_scheduled...
... started 16:35:23. Current memory use 11.5Mo.
... no workshops awaiting scheduled allocation. done. (1 dbqueries, 0 seconds)
Finished workshop allocation methods
... used 6 dbqueries
... used 0.039516925811768 seconds
done.
Processing module function checklist_cron ...
... used 1 dbqueries
... used 0.0036289691925049 seconds
done.
Finished activity modules
Starting blocks
Processing cron function for recent_activity....done.
Finished blocks
Starting admin reports
Finished admin reports
Starting course reports
Finished course reports
Starting gradebook plugins
Finished gradebook plugins
Starting repository plugins
Processing cron function for repository_dropbox...
... started 16:35:23. Current memory use 11.8Mo.
done. (1 dbqueries, 0 seconds)
Processing cron function for repository_filesystem...
... started 16:35:23. Current memory use 11.8Mo.
done. (3 dbqueries, 0 seconds)
Finished repository plugins
... used 26 dbqueries
... used 0.35069680213928 seconds
Scheduled task complete: Traitement du cron des plugins obsolètes (core\task\legacy_plugin_cron_task)
Execute scheduled task: Traitement en tâche de fond du carnet de notes (core\task\grade_cron_task)
... started 16:35:33. Current memory use 11.8Mo.
    Deleted old grade history records from 'grade_outcomes_history'
    Deleted old grade history records from 'grade_categories_history'
    Deleted old grade history records from 'grade_items_history'
    Deleted old grade history records from 'grade_grades_history'
    Deleted old grade history records from 'scale_history'
... used 7 dbqueries
... used 0.00453782081604 seconds
Scheduled task complete: Traitement en tâche de fond du carnet de notes (core\task\grade_cron_task)
Cron script completed correctly
Cron completed at 16:35:43. Memory used 11.8Mo.
Execution took 129.337479 seconds

Pour répondre à ta question, je n'ai modifié aucune ligne de lancement du cron...il est lancé par une tâche planifiée sur mon Centos 

"/usr/bin/php /var/www/vhosts/foad.swimmingpole.fr/moodle/admin/cli/cron.php >/dev/null" en tant que "style cron"

PS: souvent le message suivant lorsque je le lance à la main:

!!! L'opération s'est interrompue dans l'attente d'un verrouillage. !!!

tu me confirmes bien que c'est alors qu'il est en train de se faire et que deux session de cron ne peuvent avoir lieu ensemble ?

En te remerciant !

En réponse à Laurent Labidi

Re: cron très long

par Séverin Terrier,
Avatar Documentation writers Avatar Moodleurs particulièrement utiles Avatar Testeurs Avatar Traducteurs

Effectivement, s'il y a déjà un cron qui tourne de façon automatique, et qu'en plus tu le lances à la main, cela risque de générer des blocages.

Normalement, depuis Moodle 2.7, il y a un système de verrouillage pour éviter que la même tâche soit lancée par deux cron différents...

En réponse à Séverin Terrier

Re: cron très long

par Laurent Labidi,

Merci pour la réponse.

Du coup, en ce moment, je reçois ceci:

"Default exception handler: L'opération s'est interrompue dans l'attente d'un verrouillage. Debug:
Error code: locktimeout
* line 461 of /lib/classes/task/manager.php: moodle_exception thrown
* line 66 of /lib/cronlib.php: call to core\task\manager::get_next_scheduled_task()
* line 61 of /admin/cli/cron.php: call to cron_run()"

Cela correspond-il au fameux système de vérouillage ? Du coup, je viens de passer de 5 min de décalage entre deux crons à 15 min...on verra bien demain si j'ai à nouveau les messages.

Bonne fin de semaine !



En réponse à Laurent Labidi

Re: cron très long

par Zabelle Motte,
Avatar Moodleurs particulièrement utiles

Bonjour Laurent,

Nous sommes confrontés au même problème sur notre Moodle en ce moment.
Ton rééchelonnage du cron a t'il permi de résoudre ton problème ?

D'avance merci,


Zabelle