Projet

Général

Profil

Demande #3773

Augmenter les ressources de la VM adl

Ajouté par Christian P. Momon il y a presque 5 ans. Mis à jour il y a plus de 4 ans.

Statut:
Fermé
Priorité:
Normale
Assigné à:
Christian P. Momon
Catégorie:
-
Version cible:
Été 2019
Début:
17/06/2019
Echéance:
% réalisé:

0%

Temps estimé:
Difficulté:
2 Facile

Description

Pendant l'April camp de juin, Echarp nous a remonté que le mysql de la VM adl avait parfois des soucis en pic de charge.

Le site web agendadulibre.org connait un véritable engouement, tant de webonautes que de bots.

Demande/suggestion :
  • augmenté un petit peu la mémoire (avait été diminué lors d'une revue des VM) ;
  • passer de 1 à 2 processeurs.

Fichiers

slow_query-20190721.log (159 ko) slow_query-20190721.log Christian P. Momon, 21/07/2019 19:01

Demandes liées

Lié à Admins - Demande #3551: Configurer nginx@bastion pour limiter les requêtesEn cours de traitement10/01/2019

Actions

Historique

#1

Mis à jour par Christian P. Momon il y a presque 5 ans

Configuration actuelle :
  • MemTotal: 2 052 448 kB ;
  • CPU : 1.
#2

Mis à jour par Christian P. Momon il y a presque 5 ans

Ajout d'un fichier cron (/etc/cron.d/cpmlog) pour mettre en log quelques infos : charge moyenne (LOADAVG), mémoire libre (MEMFREE), mémoire disponible (MEMAVAILABLE), nombre de processus Ruby.
Mesure temporaire et non nominale pour mieux comprendre les problèmes de charge.

#3

Mis à jour par Christian P. Momon il y a presque 5 ans

  • Lié à Demande #3551: Configurer nginx@bastion pour limiter les requêtes ajouté
#4

Mis à jour par Christian P. Momon il y a presque 5 ans

  • Statut changé de Nouveau à En cours de traitement

Sur IRC#april-admin le 03/07/2019 :

21:09 -!- vivivi[2] is now known as vivivi[3]
[…]
21:21 < cpm_screen> !list
21:21 < vivivi[3]> 3 problemes enregistres
21:21 < vivivi[3]> [00] bastion:Check Secure Web www.agendadulibre.org is CRITICAL: HTTP CRITICAL - Invalid HTTP response received from host on port 443: HTTP/1.1 503 Service Unavailable

En allant sur https://www.agendadulibre.org/ :

This website is under heavy load (queue full)

We're sorry, too many people are accessing this website at the same time. We're working on this problem. Please try again later.

En allant sur la vm adl :

top - 21:35:14 up 14 days, 22:06,  1 user,  load average: 0,62, 1,39, 1,63
Tasks: 103 total,   1 running, 102 sleeping,   0 stopped,   0 zombie
%Cpu(s): 18,5 us,  5,1 sy,  0,0 ni, 73,5 id,  2,8 wa,  0,0 hi,  0,0 si,  0,1 st
KiB Mem :  2052448 total,   231260 free,  1272724 used,   548464 buff/cache
KiB Swap:   974844 total,   970468 free,     4376 used.   597608 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                                                                    
15147 mysql     20   0  650116 111072  16924 S 93,8  5,4   0:50.88 mysqld

Action : redémarrage du service mysqld et ça refonctionne.

#5

Mis à jour par Christian P. Momon il y a presque 5 ans

Consolidation des logs spécifiques mises en place (une ligne par minute) :

                   UPTIME MEMTOTAL       MEMFREE  MEMAVAIL RUBYCOUNT HTTPALL HTTPBOT    HTTPHUM HTTPTOPIP
2019-07-03-210001  0.56   2052448        93472    478632         3       62      57      5       20
2019-07-03-210101  0.50   2052448        92880    478384         3       96      69      27      21
2019-07-03-210201  0.79   2052448        92152    477752         3       105     87      18      25
2019-07-03-210301  0.69   2052448        92756    478416         3       95      66      29      23
2019-07-03-210401  0.78   2052448        77128    401320         3       114     91      23      23
2019-07-03-210501  1.33   2052448        150352   474728         3       114     82      32      22
2019-07-03-210601  1.80   2052448        156832   481396         3       120     92      28      20
2019-07-03-210701  1.56   2052448        156264   481052         3       121     74      47      24
2019-07-03-210801  1.35   2052448        156368   481412         3       129     84      45      21      <- début incident
2019-07-03-210901  1.80   2052448        152296   477860         3       23      14      9       5
2019-07-03-211001  1.96   2052448        144496   470312         3       1       0       1       1
2019-07-03-211101  2.02   2052448        137576   463848         3       130     47      83      49         
2019-07-03-211201  2.04   2052448        140724   467460         3       123     74      49      22
2019-07-03-211301  2.04   2052448        141412   468320         3       119     92      27      20
2019-07-03-211401  2.11   2052448        141288   468332         3       119     97      22      20
2019-07-03-211501  2.07   2052448        141072   468264         3       134     105     29      20
2019-07-03-211601  2.06   2052448        140888   468212         3       135     103     32      20
2019-07-03-211701  2.05   2052448        140044   467512         3       143     104     39      20
2019-07-03-211801  2.05   2052448        140700   468292         3       133     108     25      20
2019-07-03-211901  2.14   2052448        140608   468328         3       131     106     25      20
2019-07-03-212001  2.08   2052448        140168   468056         3       148     112     36      20
2019-07-03-212101  2.06   2052448        139880   467904         3       135     111     24      20
2019-07-03-212201  2.05   2052448        135448   463620         3       128     108     20      20
2019-07-03-212301  2.05   2052448        136444   464748         3       122     105     17      20
2019-07-03-212401  2.10   2052448        136296   464724         3       127     111     16      17
2019-07-03-212501  2.12   2052448        137004   465544         3       115     94      21      20
2019-07-03-212601  2.07   2052448        139456   468124         3       115     85      30      20
2019-07-03-212701  2.06   2052448        135048   463876         3       109     80      29      20
2019-07-03-212801  2.05   2052448        135772   464716         3       92      86      6       20
2019-07-03-212901  2.10   2052448        135632   464688         3       91      81      10      20
2019-07-03-213001  2.07   2052448        126876   460812         3       98      85      13      20
2019-07-03-213101  2.06   2052448        121644   460760         3       102     85      17      20
2019-07-03-213201  2.05   2052448        120232   459616         3       100     86      14      20
2019-07-03-213301  1.27   2052448        249484   615176         3       79      71      8       22          <- rémarrage service mysqld
2019-07-03-213401  0.69   2052448        237212   603248         3       120     75      45      25
2019-07-03-213501  0.69   2052448        231664   597972         3       112     65      47      32
2019-07-03-213601  0.77   2052448        227568   594024         3       112     76      36      24
2019-07-03-213701  0.66   2052448        224120   590680         3       85      58      27      25
2019-07-03-213801  0.66   2052448        223540   590244         3       84      75      9       23
2019-07-03-213901  0.95   2052448        222236   589084         3       72      65      7       23
2019-07-03-214001  0.54   2052448        107572   480968         3       73      59      14      21
2019-07-03-214101  0.66   2052448        108808   482404         3       74      62      12      20
2019-07-03-214201  0.42   2052448        105296   479036         3       78      65      13      21
2019-07-03-214301  0.36   2052448        107516   481516         3       84      70      14      21
2019-07-03-214401  0.41   2052448        107080   481284         3       78      67      11      23
2019-07-03-214501  0.42   2052448        166844   541304         3       84      64      20      21
2019-07-03-214601  0.35   2052448        166588   541212         3       80      69      11      20
2019-07-03-214701  0.39   2052448        133780   525664         3       82      64      18      20
2019-07-03-214801  0.44   2052448        134284   526320         3       86      70      16      20
2019-07-03-214901  0.55   2052448        133412   525756         3       102     64      38      24
2019-07-03-215001  0.38   2052448        133188   525712         3       79      69      10      21
2019-07-03-215101  0.35   2052448        131168   524416         3       87      70      17      23
2019-07-03-215201  0.37   2052448        127828   524020         3       81      65      16      23

Reste à tirer quelque chose de ces informations :
  • problème de mémoire ? Pas vraiment.
  • surcharge CPU ? Bof.
  • nombre de requêtes ? 129 par minutes serait un maximum ?
  • un bot qui s'emballe ? L'ip ayant le plus de requêtes par minute ne dépasse 20 req/min, chiffre globalement constant.

Une interprétation pourrait être que le nombre de requêtes bots a été constant mais qu'il y a eu un pic de requêtes humaines amenant au maximum de requêtes traitables par le serveur.

Questions :
  • est-ce que 129 requêtes par minutes est un maximum crédible ?
  • quoi augmenter pour absorber un tel pic ?
  • vu que ça semble ne pas être un problème de mémoire ni de nombre de CPU :
    • est-il possible/utile d'augmenter le nombre de thread mysql ?
    • est-il possible/utile d'augmenter le nombre de thread apache ?
    • est-il possible/utile d'augmenter le nombre de thread ruby ?
#6

Mis à jour par Christian P. Momon il y a presque 5 ans

Re-problème ce matin :

                      UPTIME MEMTOTAL MEMFREE MEMAVAIL RUBYCOUNT HTTPALL HTTPBOT HTTPHUM HTTPTOPIP
2019-07-04-071801       0.12    2052448 228608  751864  3       57      42      15      20
2019-07-04-071901       0.15    2052448 228492  751832  3       55      50      5       20
2019-07-04-072001       0.17    2052448 227596  751028  3       53      44      9       20
2019-07-04-072101       0.32    2052448 227444  750972  3       70      57      13      20
2019-07-04-072201       0.25    2052448 212052  735856  3       59      53      6       20
2019-07-04-072301       0.25    2052448 211900  735764  3       52      46      6       20
2019-07-04-072401       0.55    2052448 210172  734152  3       72      44      28      19
2019-07-04-072501       1.71    2052448 205728  729804  3       2       2       0       1
2019-07-04-072601       1.95    2052448 201776  725952  3       1       0       1       1
2019-07-04-072701       1.98    2052448 199016  723312  3       1       0       1       1
2019-07-04-072801       2.00    2052448 196396  720820  3       112     39      73      45
2019-07-04-072901       2.06    2052448 196092  720656  3       112     49      63      56
2019-07-04-073001       2.10    2052448 194936  719620  3       122     61      61      54
2019-07-04-073101       2.07    2052448 194764  719548  3       67      54      13      20
2019-07-04-073201       2.02    2052448 195772  720640  3       65      56      9       20
2019-07-04-073301       2.01    2052448 195672  720636  3       73      58      15      20
2019-07-04-073402       2.00    2052448 195424  720460  3       71      62      9       20
2019-07-04-073501       2.00    2052448 194552  719708  3       81      64      17      20
2019-07-04-073601       2.00    2052448 194648  719904  3       81      60      21      20
2019-07-04-073701       2.00    2052448 195580  720924  3       68      62      6       20
[…]
2019-07-04-095401       2.05    2052448 178000  716288  3       55      47      8       20
2019-07-04-095501       2.12    2052448 176592  714988  3       74      44      30      20
2019-07-04-095601       2.07    2052448 176776  715240  3       63      51      12      20
2019-07-04-095701       2.14    2052448 177632  716148  3       56      44      12      20
2019-07-04-095801       2.08    2052448 177500  716060  3       62      46      16      20
2019-07-04-095901       2.06    2052448 177404  716028  3       64      54      10      20
2019-07-04-100001       1.74    2052448 331068  871696  3       65      53      12      20
2019-07-04-100101       1.38    2052448 312452  854020  3       117     54      63      24
2019-07-04-100201       0.89    2052448 282800  841932  3       81      55      26      20
2019-07-04-100301       0.67    2052448 278756  838300  3       73      58      15      22
2019-07-04-100401       0.24    2052448 278928  838616  3       67      52      15      20
2019-07-04-100501       0.42    2052448 268956  828864  3       77      55      22      20
2019-07-04-100601       0.35    2052448 265880  825920  3       101     65      36      20
2019-07-04-100701       0.30    2052448 263524  823684  3       115     71      44      26
2019-07-04-100801       0.50    2052448 165992  726264  3       83      64      19      20
2019-07-04-100901       0.79    2052448 177252  738056  3       106     75      31      20
2019-07-04-101001       0.54    2052448 175240  736132  3       92      78      14      20
2019-07-04-101101       0.44    2052448 171400  732380  3       91      80      11      20
2019-07-04-101201       0.42    2052448 176048  737124  3       88      82      6       21
2019-07-04-101301       0.59    2052448 166812  728000  3       115     92      23      20
2019-07-04-101401       0.37    2052448 166368  727672  3       127     104     23      20
2019-07-04-101501       0.31    2052448 155920  717292  3       102     88      14      20
2019-07-04-101601       0.56    2052448 163476  724920  3       121     84      37      23
2019-07-04-101701       0.55    2052448 164032  725636  3       124     90      34      20
2019-07-04-101801       1.14    2052448 163112  724960  3       164     91      73      31
2019-07-04-101901       0.87    2052448 125508  687540  3       144     93      51      21
2019-07-04-102001       0.75    2052448 170868  733356  3       119     89      30      20
2019-07-04-102101       0.71    2052448 159664  722608  3       116     90      26      20

#7

Mis à jour par Christian P. Momon il y a presque 5 ans

  • Version cible changé de Backlog à Été 2019
#8

Mis à jour par Christian P. Momon il y a presque 5 ans

  • Assigné à mis à Christian P. Momon

Enrichissement conf pour les logs:

slow_query_log
slow_query_log_file           = /var/log/mysql/slow_query.log
long_query_time               = 10
log_slow_rate_limit           = 1000
log_slow_verbosity            = query_plan
log_queries_not_using_indexes = ON

#9

Mis à jour par Christian P. Momon il y a presque 5 ans

Suite à la configuration de log supplémentaires, analyse du fichier slow_query.log.
Rien vu de spécial.

#10

Mis à jour par Christian P. Momon il y a plus de 4 ans

Il y a quelques temps, ajout de points de mesure sur le swap. Résultat :

(April) root@adl:~/Cpm# ./dopaste
                   UPTIME MEMTOTAL       MEMFREE  MEMAVAIL RUBYCOUNT HTTPALL HTTPBOT HTTPHUM HTTPTOPIP SWAPTOTAL SWAPFREE SWAPUSED
2019-08-10-171401       0.17    2052448 106724  435812  3       41      28      13      5       974844  964020  10824
2019-08-10-171501       0.21    2052448 105468  434732  3       40      31      9       6       974844  964020  10824
2019-08-10-171601       0.44    2052448 105408  434832  3       50      30      20      5       974844  964020  10824
2019-08-10-171701       0.48    2052448 105932  435516  3       50      28      22      5       974844  964020  10824
2019-08-10-171801       0.31    2052448 105960  435668  3       37      27      10      4       974844  964020  10824
2019-08-10-171901       0.35    2052448 105476  435412  3       46      38      8       7       974844  964020  10824
2019-08-10-172001       0.40    2052448 102296  432684  3       46      33      13      8       974844  964020  10824
2019-08-10-172101       0.41    2052448 95420   428436  3       45      31      14      6       974844  964020  10824

Côté log slow_query :

(April) root@adl:/var/log/mysql# grep Query_time slow_query.log
# Query_time: 0.242211  Lock_time: 0.000044  Rows_sent: 25  Rows_examined: 28675
# Query_time: 0.107672  Lock_time: 0.000053  Rows_sent: 24  Rows_examined: 17433
# Query_time: 0.114628  Lock_time: 0.000053  Rows_sent: 2  Rows_examined: 17433
# Query_time: 0.164427  Lock_time: 0.000056  Rows_sent: 24  Rows_examined: 17434
# Query_time: 0.155710  Lock_time: 0.000059  Rows_sent: 24  Rows_examined: 17434
# Query_time: 0.227035  Lock_time: 0.000045  Rows_sent: 25  Rows_examined: 29225
# Query_time: 0.198143  Lock_time: 0.000051  Rows_sent: 18  Rows_examined: 17436
# Query_time: 0.338800  Lock_time: 0.000043  Rows_sent: 25  Rows_examined: 29250

#11

Mis à jour par Christian P. Momon il y a plus de 4 ans

  • Statut changé de En cours de traitement à Attente d'information

Puisque le swap est régulièrement impacté (environ 10 Mo), actions suivantes :

1) augmentation de la RAM de 256 Mo (2 052 448 kB -> 2 310 356 KB) ;

2) passage de 1 processeur à 2 ;

3) demande à echarp d'analyser les log slow_query.

À voir en septembre comment le site se comporte avec ces changements.

#12

Mis à jour par Christian P. Momon il y a plus de 4 ans

Constat le 12/08/2019 que mysql est en souffrance. Tentative d'investigation pendant le crash.

Firefox
Le site web répond ça :

This website is under heavy load (queue full)

We're sorry, too many people are accessing this website at the same time. We're working on this problem. Please try again later.

Top
Un top répond ça :


top - 02:16:24 up 2 days,  8:50,  1 user,  load average: 2,06, 2,07, 2,07
Tasks: 115 total,   1 running, 113 sleeping,   1 stopped,   0 zombie
%Cpu(s): 99,5 us,  0,5 sy,  0,0 ni,  0,0 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st
KiB Mem :  2310356 total,    93872 free,  1506532 used,   709952 buff/cache
KiB Swap:   974844 total,   974488 free,      356 used.   587992 avail Mem 
  scroll coordinates: y = 1/115 (tasks), x = 1/12 (fields)
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                                                                                        
  755 mysql     20   0  678988 244752   8156 S 199,1 10,6 833:00.95 mysqld                                                                                                                                                                                         
    1 root      20   0  204500   3912   2640 S   0,0  0,2   0:02.51 systemd                                                                                                                                                                                        
    2 root      20   0       0      0      0 S   0,0  0,0   0:00.01 kthreadd

Apache
Les logs Apache sur vm adl sont plutôt tranquilles, pas de flood mais que du 503 (Service Unavailable) :

(April) root@adl:/var/log#  tail -f apache2/agendadulibre.org.access.log
5.9.156.121 - - [13/Aug/2019:02:17:58 +0200] "GET /events/19589?region=123 HTTP/1.0" 503 516 "-" "Mozilla/5.0 (compatible; MJ12bot/v1.4.8; http://mj12bot.com/)" 
88.184.244.236 - - [13/Aug/2019:02:17:59 +0200] "GET /events.rss?near%5Blocation%5D=Nantes&near%5Bdistance%5D=45&region=18 HTTP/1.0" 503 516 "-" "NextCloud-News/1.0" 
5.9.156.121 - - [13/Aug/2019:02:18:02 +0200] "GET /events/19589?region=125 HTTP/1.0" 503 516 "-" "Mozilla/5.0 (compatible; MJ12bot/v1.4.8; http://mj12bot.com/)" 
157.55.39.92 - - [13/Aug/2019:02:18:03 +0200] "GET /events/10365?region=92 HTTP/1.0" 503 516 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)" 
90.92.201.161 - - [13/Aug/2019:02:18:05 +0200] "GET /events.rss?region=3 HTTP/1.0" 503 516 "https://www.agendadulibre.org/events.rss?region=3" "FreshRSS/1.14.3 (Linux; https://freshrss.org)" 
5.9.156.121 - - [13/Aug/2019:02:18:05 +0200] "GET /events/19589?region=126 HTTP/1.0" 503 516 "-" "Mozilla/5.0 (compatible; MJ12bot/v1.4.8; http://mj12bot.com/)" 
207.46.13.46 - - [13/Aug/2019:02:18:08 +0200] "GET /events/14306?region=32 HTTP/1.0" 503 516 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)" 
5.9.156.121 - - [13/Aug/2019:02:18:09 +0200] "GET /events/19589?region=127 HTTP/1.0" 503 516 "-" "Mozilla/5.0 (compatible; MJ12bot/v1.4.8; http://mj12bot.com/)" 
5.9.156.121 - - [13/Aug/2019:02:18:12 +0200] "GET /events/19589?region=128 HTTP/1.0" 503 516 "-" "Mozilla/5.0 (compatible; MJ12bot/v1.4.8; http://mj12bot.com/)"

Aucune erreur dans les logs Apache vm adl ?!!

Nginx
Côté vm bastion, pas de flood mais du 503 :

==> agendadulibre.org.access_log <==
157.55.39.92 - - [13/Aug/2019:02:21:13 +0200] "GET /events/18277?region=32 HTTP/1.1" 503 189 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)" 
54.36.148.70 - - [13/Aug/2019:02:21:14 +0200] "GET /events/19063.ics HTTP/1.1" 503 189 "-" "Mozilla/5.0 (compatible; AhrefsBot/6.1; +http://ahrefs.com/robot/)" 
5.9.156.121 - - [13/Aug/2019:02:21:14 +0200] "GET /events?region=1&start_date=2016-11-01&tag=Alsace%20R%C3%A9seau%20Neutre HTTP/1.1" 503 189 "-" "Mozilla/5.0 (compatible; MJ12bot/v1.4.8; http://mj12bot.com/)" 
46.229.168.151 - - [13/Aug/2019:02:21:14 +0200] "GET /events/1486.ics HTTP/1.1" 503 189 "-" "Mozilla/5.0 (compatible; SemrushBot/3~bl; +http://www.semrush.com/bot.html)" 
137.74.202.107 - - [13/Aug/2019:02:21:17 +0200] "GET /events.rss?tag=openstreetmap&daylimit=20 HTTP/1.1" 503 189 "https://www.agendadulibre.org/events.rss?tag=openstreetmap&daylimit=20" "WordPress/5.2.2; http://www.openstreetmap.fr" 
94.237.57.97 - - [13/Aug/2019:02:21:17 +0200] "GET /events.rss?near%5Blocation%5D=strasbourg&near%5Bdistance%5D=50&region=1 HTTP/1.1" 503 189 "-" "Go-NEB" 
137.74.202.107 - - [13/Aug/2019:02:21:17 +0200] "GET /events.rss?tag=openstreetmap&daylimit=20 HTTP/1.1" 503 189 "https://www.agendadulibre.org/events.rss?tag=openstreetmap&daylimit=20" "WordPress/5.2.2; http://www.openstreetmap.fr" 
5.9.156.121 - - [13/Aug/2019:02:21:18 +0200] "GET /events?region=1&start_date=2016-11-01&tag=Carrefour%20num%C3%A9rique%C2%B2 HTTP/1.1" 302 161 "-" "Mozilla/5.0 (compatible; MJ12bot/v1.4.8; http://mj12bot.com/)" 
207.46.13.123 - - [13/Aug/2019:02:21:18 +0200] "GET /events/9356?region=36 HTTP/1.1" 503 189 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)" 
46.229.168.153 - - [13/Aug/2019:02:21:20 +0200] "GET /maps.json?tag=seminaire HTTP/1.1" 503 189 "-" "Mozilla/5.0 (compatible; SemrushBot/3~bl; +http://www.semrush.com/bot.html)" 
54

Par contre, les erreurs sont bloquées au début de l'incident :

(April) root@bastion:/var/log/nginx/agendadulibre.org# tail -1100 agendadulibre.org.error_log
2019/08/12 16:58:03 [error] 11035#11035: *25493226 access forbidden by rule, client: 217.147.169.240, server: agendadulibre.org, request: "GET /.git/HEAD HTTP/1.1", host: "www.agendadulibre.be" 
2019/08/12 17:02:33 [error] 11035#11035: *25496215 access forbidden by rule, client: 217.147.169.240, server: agendadulibre.org, request: "GET /.git/HEAD HTTP/1.1", host: "www.agendadulibre.org" 
2019/08/12 21:15:27 [error] 11035#11035: *25631028 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 69.30.226.234, server: agendadulibre.org, request: "GET /events?region=7&start_date=2010-02-01&tag=linux HTTP/1.1", upstream: "http://172.16.0.10:80/events?region=7&start_date=2010-02-01&tag=linux", host: "www.agendadulibre.org" 
2019/08/12 21:15:40 [error] 11035#11035: *25638013 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 217.146.225.31, server: agendadulibre.org, request: "GET /events.json?region=12 HTTP/1.0", upstream: "http://172.16.0.10:80/events.json?region=12", host: "www.agendadulibre.org" 
2019/08/12 21:15:46 [error] 11035#11035: *25638035 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 90.107.168.245, server: agendadulibre.org, request: "GET /events.ics?tag=OpenStreetMap-France HTTP/1.1", upstream: "http://172.16.0.10:80/events.ics?tag=OpenStreetMap-France", host: "www.agendadulibre.org" 
2019/08/12 21:15:46 [error] 11035#11035: *25638041 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 90.107.168.245, server: agendadulibre.org, request: "GET /events.ics?region=18 HTTP/1.1", upstream: "http://172.16.0.10:80/events.ics?region=18", host: "www.agendadulibre.org" 
2019/08/12 21:15:46 [error] 11035#11035: *25638040 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 90.107.168.245, server: agendadulibre.org, request: "GET /events.ics?tag=Franciliens-net HTTP/1.1", upstream: "http://172.16.0.10:80/events.ics?tag=Franciliens-net", host: "www.agendadulibre.org" 
2019/08/12 21:15:46 [error] 11035#11035: *25638042 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 90.107.168.245, server: agendadulibre.org, request: "GET /events.ics?tag=Jungle-Bus HTTP/1.1", upstream: "http://172.16.0.10:80/events.ics?tag=Jungle-Bus", host: "www.agendadulibre.org" 
2019/08/12 21:15:46 [error] 11035#11035: *25638044 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 90.107.168.245, server: agendadulibre.org, request: "GET /events.ics?tag=Open-Event-France HTTP/1.1", upstream: "http://172.16.0.10:80/events.ics?tag=Open-Event-France", host: "www.agendadulibre.org" 
2019/08/12 21:15:46 [error] 11035#11035: *25638043 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 90.107.168.245, server: agendadulibre.org, request: "GET /events.ics?region=12 HTTP/1.1", upstream: "http://172.16.0.10:80/events.ics?region=12", host: "www.agendadulibre.org" 
2019/08/12 21:15:48 [error] 11035#11035: *25638058 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 37.168.211.120, server: agendadulibre.org, request: "GET /events.ics?region=4 HTTP/1.1", upstream: "http://172.16.0.10:80/events.ics?region=4", host: "www.agendadulibre.org" 
2019/08/12 21:16:15 [error] 11035#11035: *25638286 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 94.237.57.97, server: agendadulibre.org, request: "GET /events.rss?near%5Blocation%5D=strasbourg&near%5Bdistance%5D=50&region=1 HTTP/1.1", upstream: "http://172.16.0.10:80/events.rss?near%5Blocation%5D=strasbourg&near%5Bdistance%5D=50&region=1", host: "www.agendadulibre.org" 
2019/08/12 21:16:15 [error] 11035#11035: *25638284 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 69.30.226.234, server: agendadulibre.org, request: "GET /events?region=7&start_date=2010-02-01&tag=linux HTTP/1.1", upstream: "http://172.16.0.10:80/events?region=7&start_date=2010-02-01&tag=linux", host: "www.agendadulibre.org" 
2019/08/12 21:16:23 [error] 11035#11035: *25638336 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 65.132.59.34, server: agendadulibre.org, request: "GET /events/19463?region=114 HTTP/1.1", upstream: "http://172.16.0.10:80/events/19463?region=114", host: "www.agendadulibre.org" 
2019/08/12 21:16:25 [error] 11035#11035: *25638374 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 176.158.165.22, server: agendadulibre.org, request: "GET /events/10671 HTTP/1.1", upstream: "http://172.16.0.10:80/events/10671", host: "www.agendadulibre.org", referrer: "https://www.google.com/"

Collecte spéciale

(April) root@adl:~/Cpm# ./dopaste
                   UPTIME MEMTOTAL       MEMFREE  MEMAVAIL RUBYCOUNT HTTPALL HTTPBOT HTTPHUM HTTPTOPIP SWAPTOTAL SWAPFREE SWAPUSED
2019-08-12-211001       0.09    2310356 79628   706240  3       51      38      13      9       974844  974804  40
2019-08-12-211101       0.16    2310356 79832   716208  3       61      40      21      9       974844  974796  48
2019-08-12-211201       0.27    2310356 105208  716960  3       53      39      14      7       974844  974768  76
2019-08-12-211301       0.33    2310356 105276  717068  3       47      32      15      7       974844  974768  76
2019-08-12-211401       0.29    2310356 78376   714520  3       50      35      15      7       974844  974764  80
2019-08-12-211501       1.78    2310356 140240  677972  3       141     15      126     123     974844  974764  80
2019-08-12-211601       3.29    2310356 103360  512504  3       1       0       1       1       974844  974760  84
2019-08-12-211702       3.42    2310356 85928   497112  3       13      4       9       3       974844  974760  84
2019-08-12-211801       1.91    2310356 175948  589528  3       94      52      42      23      974844  974760  84
2019-08-12-211901       0.73    2310356 174284  588668  3       52      39      13      15      974844  974760  84
2019-08-12-212001       0.51    2310356 93324   589716  3       71      51      20      12      974844  974760  84
2019-08-12-212101       0.27    2310356 79212   589020  3       50      39      11      7       974844  974744  100
2019-08-12-212201       0.38    2310356 94816   589048  3       48      41      7       7       974844  974744  100
2019-08-12-212301       0.27    2310356 108056  605556  3       54      36      18      10      974844  974744  100
2019-08-12-212401       0.13    2310356 107348  605124  3       55      35      20      11      974844  974744  100
2019-08-12-212501       0.09    2310356 107064  604988  3       49      32      17      7       974844  974744  100
2019-08-12-212601       0.09    2310356 107392  605668  3       58      38      20      7       974844  974744  100
2019-08-12-212701       0.03    2310356 106480  605892  3       52      39      13      7       974844  974744  100
2019-08-12-212801       0.01    2310356 105988  605644  3       37      21      16      6       974844  974744  100
2019-08-12-212901       0.18    2310356 105120  605072  3       37      26      11      7       974844  974744  100
2019-08-12-213001       0.06    2310356 105736  605824  3       43      27      16      7       974844  974744  100
2019-08-12-213101       0.30    2310356 102292  605552  3       61      30      31      11      974844  974744  100
2019-08-12-213201       0.15    2310356 102316  605768  3       44      31      13      7       974844  974744  100
2019-08-12-213301       0.25    2310356 101928  605624  3       45      30      15      7       974844  974744  100
2019-08-12-213401       0.26    2310356 100768  604624  3       47      32      15      6       974844  974744  100
2019-08-12-213501       0.09    2310356 101868  605880  3       71      43      28      6       974844  974744  100
2019-08-12-213601       0.13    2310356 101480  605644  3       60      44      16      15      974844  974744  100
2019-08-12-213701       0.25    2310356 101304  605840  3       102     59      43      30      974844  974744  100
2019-08-12-213801       1.03    2310356 100124  605472  3       97      50      47      20      974844  974744  100
2019-08-12-213901       1.65    2310356 98244   603736  3       2       2       0       1       974844  974744  100
2019-08-12-214001       1.87    2310356 94812   600512  3       1       1       0       1       974844  974744  100
2019-08-12-214101       2.04    2310356 91612   597512  3       100     37      63      46      974844  974744  100
2019-08-12-214201       2.05    2310356 90788   596844  3       136     65      71      29      974844  974744  100
2019-08-12-214301       2.05    2310356 90660   596860  3       85      63      22      17      974844  974744  100
2019-08-12-214401       2.02    2310356 89708   596048  3       66      40      26      21      974844  974744  100
2019-08-12-214501       2.00    2310356 90380   596920  3       84      43      41      32      974844  974744  100
2019-08-12-214601       2.00    2310356 90004   596672  3       78      44      34      26      974844  974744  100
2019-08-12-214701       2.00    2310356 89652   596536  3       69      49      20      7       974844  974744  100
2019-08-12-214801       2.00    2310356 89616   596624  3       57      32      25      11      974844  974744  100
2019-08-12-214901       2.00    2310356 88444   595604  3       77      39      38      17      974844  974744  100
2019-08-12-215001       2.06    2310356 89268   596612  3       67      34      33      15      974844  974744  100
2019-08-12-215101       2.02    2310356 88700   596172  3       76      40      36      20      974844  974744  100

Mysql

(April) root@adl:~/Cpm# mysqladmin -u adl_fr -p status adl_fr
Enter password: 
Uptime: 207600  Threads: 4  Questions: 3662290  Slow queries: 40558  Opens: 144  Flush tables: 1  Open tables: 138  Queries per second avg: 17.641


MariaDB [adl_fr]> show status like '%onn%';
+-----------------------------------------------+-------+
| Variable_name                                 | Value |
+-----------------------------------------------+-------+
| Aborted_connects                              | 4     |
| Connection_errors_accept                      | 0     |
| Connection_errors_internal                    | 0     |
| Connection_errors_max_connections             | 0     |
| Connection_errors_peer_address                | 0     |
| Connection_errors_select                      | 0     |
| Connection_errors_tcpwrap                     | 0     |
| Connections                                   | 1429  |
| Max_used_connections                          | 4     |
| Performance_schema_session_connect_attrs_lost | 0     |
| Slave_connections                             | 0     |
| Slaves_connected                              | 0     |
| Ssl_client_connects                           | 0     |
| Ssl_connect_renegotiates                      | 0     |
| Ssl_finished_connects                         | 0     |
| Threads_connected                             | 3     |
| wsrep_connected                               | OFF   |
+-----------------------------------------------+-------+

MariaDB [adl_fr]> SHOW STATUS LIKE 'Key%';
+------------------------+------------+
| Variable_name          | Value      |
+------------------------+------------+
| Key_blocks_not_flushed | 0          |
| Key_blocks_unused      | 12768      |
| Key_blocks_used        | 621        |
| Key_blocks_warm        | 500        |
| Key_read_requests      | 3538770772 |
| Key_reads              | 620        |
| Key_write_requests     | 40         |
| Key_writes             | 40         |
+------------------------+------------+

MariaDB [adl_fr]> show processlist;
+------+--------+-----------+--------+---------+-------+------------+------------------------------------------------------------------------------------------------------+----------+
| Id   | User   | Host      | db     | Command | Time  | State      | Info                                                                                                 | Progress |
+------+--------+-----------+--------+---------+-------+------------+------------------------------------------------------------------------------------------------------+----------+
|  917 | adl_fr | localhost | adl_fr | Query   | 17720 | statistics | SELECT  `events`.* FROM `events` INNER JOIN `taggings` `event_taggings_70382ac` ON `event_taggings_7 |    0.000 |
|  918 | adl_fr | localhost | adl_fr | Query   | 17690 | statistics | SELECT  `events`.* FROM `events` INNER JOIN `taggings` `event_taggings_70382ac` ON `event_taggings_7 |    0.000 |
| 1401 | adl_fr | localhost | adl_fr | Query   |     0 | init       | show processlist                                                                                     |    0.000 |
+------+--------+-----------+--------+---------+-------+------------+------------------------------------------------------------------------------------------------------+----------+
3 rows in set (0.00 sec)

Là, on peut voir que 2 process Mysql n'en finissent pas.

Pour en savoir plus :

ariaDB [adl_fr]> select * from INFORMATION_SCHEMA.PROCESSLIST where db = 'adl_fr';
| ID   | USER   | HOST      | DB     | COMMAND | TIME  | STATE                | INFO
| TIME_MS      | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
INFO_BINARY
| TID   |

|  918 | adl_fr | localhost | adl_fr | Query   | 18208 | statistics           |
SELECT  `events`.* FROM `events` INNER JOIN `taggings` `event_taggings_70382ac` ON `event_taggings_70382ac`.`taggable_id` = `events`.`id` AND `event_taggings_70382ac`.`taggable_type` = 'Event' AND `event_taggings_70382ac`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '(select' \
ESCAPE '!') INNER JOIN `taggings` `event_taggings_7dc26f5` ON `event_taggings_7dc26f5`.`taggable_id` = `events`.`id` AND `event_taggings_7dc26f5`.`taggable_type` = 'Event' AND `event_taggings_7dc26f5`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '(case' ESCAPE '!') INNER JOIN \
`taggings` `event_taggings_30603fa` ON `event_taggings_30603fa`.`taggable_id` = `events`.`id` AND `event_taggings_30603fa`.`taggable_type` = 'Event' AND `event_taggings_30603fa`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'when' ESCAPE '!') INNER JOIN `taggings` `event_taggin\
gs_be80acd` ON `event_taggings_be80acd`.`taggable_id` = `events`.`id` AND `event_taggings_be80acd`.`taggable_type` = 'Event' AND `event_taggings_be80acd`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '(7226=2977)' ESCAPE '!') INNER JOIN `taggings` `event_taggings_6f8f8e9` ON `e\
vent_taggings_6f8f8e9`.`taggable_id` = `events`.`id` AND `event_taggings_6f8f8e9`.`taggable_type` = 'Event' AND `event_taggings_6f8f8e9`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'then' ESCAPE '!') INNER JOIN `taggings` `event_taggings_6c0b333` ON `event_taggings_6c0b333`.`\
taggable_id` = `events`.`id` AND `event_taggings_6c0b333`.`taggable_type` = 'Event' AND `event_taggings_6c0b333`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '0x74657374' ESCAPE '!') INNER JOIN `taggings` `event_taggings_ae050f5` ON `event_taggings_ae050f5`.`taggable_id` = `ev\
ents`.`id` AND `event_taggings_ae050f5`.`taggable_type` = 'Event' AND `event_taggings_ae050f5`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'else' ESCAPE '!') INNER JOIN `taggings` `event_taggings_ca99ad7` ON `event_taggings_ca99ad7`.`taggable_id` = `events`.`id` AND `event_ta\
ggings_ca99ad7`.`taggable_type` = 'Event' AND `event_taggings_ca99ad7`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '2977' ESCAPE '!') INNER JOIN `taggings` `event_taggings_67ad5a0` ON `event_taggings_67ad5a0`.`taggable_id` = `events`.`id` AND `event_taggings_67ad5a0`.`taggabl\
e_type` = 'Event' AND `event_taggings_67ad5a0`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'union' ESCAPE '!') INNER JOIN `taggings` `event_taggings_81448fe` ON `event_taggings_81448fe`.`taggable_id` = `events`.`id` AND `event_taggings_81448fe`.`taggable_type` = 'Event' AND `\
event_taggings_81448fe`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'select' ESCAPE '!') INNER JOIN `taggings` `event_taggings_7cceec5` ON `event_taggings_7cceec5`.`taggable_id` = `events`.`id` AND `event_taggings_7cceec5`.`taggable_type` = 'Event' AND `event_taggings_7cceec5\
`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '8769)' ESCAPE '!') INNER JOIN `taggings` `event_taggings_6d8f7d4` ON `event_taggings_6d8f7d4`.`taggable_id` = `events`.`id` AND `event_taggings_6d8f7d4`.`taggable_type` = 'Event' AND `event_taggings_6d8f7d4`.`tag_id` IN (SELECT `\
tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'end))' ESCAPE '!') WHERE `events`.`moderated` = 1 AND ('2019-07-29' <= end_time and start_time <= '2019-09-01 23:59:59.999999') ORDER BY id desc LIMIT 3000

| 18208809.168 |     0 |         0 |    0.000 |      740296 |             0 |  3661243 |
SELECT  `events`.* FROM `events` INNER JOIN `taggings` `event_taggings_70382ac` ON `event_taggings_70382ac`.`taggable_id` = `events`.`id` AND `event_taggings_70382ac`.`taggable_type` = 'Event' AND `event_taggings_70382ac`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '(select' \
ESCAPE '!') INNER JOIN `taggings` `event_taggings_7dc26f5` ON `event_taggings_7dc26f5`.`taggable_id` = `events`.`id` AND `event_taggings_7dc26f5`.`taggable_type` = 'Event' AND `event_taggings_7dc26f5`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '(case' ESCAPE '!') INNER JOIN \
`taggings` `event_taggings_30603fa` ON `event_taggings_30603fa`.`taggable_id` = `events`.`id` AND `event_taggings_30603fa`.`taggable_type` = 'Event' AND `event_taggings_30603fa`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'when' ESCAPE '!') INNER JOIN `taggings` `event_taggin\
gs_be80acd` ON `event_taggings_be80acd`.`taggable_id` = `events`.`id` AND `event_taggings_be80acd`.`taggable_type` = 'Event' AND `event_taggings_be80acd`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '(7226=2977)' ESCAPE '!') INNER JOIN `taggings` `event_taggings_6f8f8e9` ON `e\
vent_taggings_6f8f8e9`.`taggable_id` = `events`.`id` AND `event_taggings_6f8f8e9`.`taggable_type` = 'Event' AND `event_taggings_6f8f8e9`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'then' ESCAPE '!') INNER JOIN `taggings` `event_taggings_6c0b333` ON `event_taggings_6c0b333`.`\
taggable_id` = `events`.`id` AND `event_taggings_6c0b333`.`taggable_type` = 'Event' AND `event_taggings_6c0b333`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '0x74657374' ESCAPE '!') INNER JOIN `taggings` `event_taggings_ae050f5` ON `event_taggings_ae050f5`.`taggable_id` = `ev\
ents`.`id` AND `event_taggings_ae050f5`.`taggable_type` = 'Event' AND `event_taggings_ae050f5`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'else' ESCAPE '!') INNER JOIN `taggings` `event_taggings_ca99ad7` ON `event_taggings_ca99ad7`.`taggable_id` = `events`.`id` AND `event_ta\
ggings_ca99ad7`.`taggable_type` = 'Event' AND `event_taggings_ca99ad7`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '2977' ESCAPE '!') INNER JOIN `taggings` `event_taggings_67ad5a0` ON `event_taggings_67ad5a0`.`taggable_id` = `events`.`id` AND `event_taggings_67ad5a0`.`taggabl\
e_type` = 'Event' AND `event_taggings_67ad5a0`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'union' ESCAPE '!') INNER JOIN `taggings` `event_taggings_81448fe` ON `event_taggings_81448fe`.`taggable_id` = `events`.`id` AND `event_taggings_81448fe`.`taggable_type` = 'Event' AND `\
event_taggings_81448fe`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'select' ESCAPE '!') INNER JOIN `taggings` `event_taggings_7cceec5` ON `event_taggings_7cceec5`.`taggable_id` = `events`.`id` AND `event_taggings_7cceec5`.`taggable_type` = 'Event' AND `event_taggings_7cceec5\
`.`tag_id` IN (SELECT `tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE '8769)' ESCAPE '!') INNER JOIN `taggings` `event_taggings_6d8f7d4` ON `event_taggings_6d8f7d4`.`taggable_id` = `events`.`id` AND `event_taggings_6d8f7d4`.`taggable_type` = 'Event' AND `event_taggings_6d8f7d4`.`tag_id` IN (SELECT `\
tags`.`id` FROM `tags` WHERE LOWER(`tags`.`name`) LIKE 'end))' ESCAPE '!') WHERE `events`.`moderated` = 1 AND ('2019-07-29' <= end_time and start_time <= '2019-09-01 23:59:59.999999') ORDER BY id desc LIMIT 3000
|  1183 |

Faudrait comprendre d'où viennent ces 2 requêts infernales. Essayons de leur donner forme :

SELECT `events`.*
FROM `events`
INNER JOIN `taggings` `event_taggings_70382ac` ON `event_taggings_70382ac`.`taggable_id` = `events`.`id`
AND `event_taggings_70382ac`.`taggable_type` = 'Event'
AND `event_taggings_70382ac`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE '(select' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_7dc26f5` ON `event_taggings_7dc26f5`.`taggable_id` = `events`.`id`
AND `event_taggings_7dc26f5`.`taggable_type` = 'Event'
AND `event_taggings_7dc26f5`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE '(case' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_30603fa` ON `event_taggings_30603fa`.`taggable_id` = `events`.`id`
AND `event_taggings_30603fa`.`taggable_type` = 'Event'
AND `event_taggings_30603fa`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE 'when' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_be80acd` ON `event_taggings_be80acd`.`taggable_id` = `events`.`id`
AND `event_taggings_be80acd`.`taggable_type` = 'Event'
AND `event_taggings_be80acd`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE '(7226=2977)' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_6f8f8e9` ON `event_taggings_6f8f8e9`.`taggable_id` = `events`.`id`
AND `event_taggings_6f8f8e9`.`taggable_type` = 'Event'
AND `event_taggings_6f8f8e9`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE 'then' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_6c0b333` ON `event_taggings_6c0b333`.`taggable_id` = `events`.`id`
AND `event_taggings_6c0b333`.`taggable_type` = 'Event'
AND `event_taggings_6c0b333`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE '0x74657374' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_ae050f5` ON `event_taggings_ae050f5`.`taggable_id` = `events`.`id`
AND `event_taggings_ae050f5`.`taggable_type` = 'Event'
AND `event_taggings_ae050f5`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE 'else' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_ca99ad7` ON `event_taggings_ca99ad7`.`taggable_id` = `events`.`id`
AND `event_taggings_ca99ad7`.`taggable_type` = 'Event'
AND `event_taggings_ca99ad7`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE '2977' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_67ad5a0` ON `event_taggings_67ad5a0`.`taggable_id` = `events`.`id`
AND `event_taggings_67ad5a0`.`taggable_type` = 'Event'
AND `event_taggings_67ad5a0`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE 'union' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_81448fe` ON `event_taggings_81448fe`.`taggable_id` = `events`.`id`
AND `event_taggings_81448fe`.`taggable_type` = 'Event'
AND `event_taggings_81448fe`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE 'select' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_7cceec5` ON `event_taggings_7cceec5`.`taggable_id` = `events`.`id`
AND `event_taggings_7cceec5`.`taggable_type` = 'Event'
AND `event_taggings_7cceec5`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE '8769)' ESCAPE '!')
INNER JOIN `taggings` `event_taggings_6d8f7d4` ON `event_taggings_6d8f7d4`.`taggable_id` = `events`.`id`
AND `event_taggings_6d8f7d4`.`taggable_type` = 'Event'
AND `event_taggings_6d8f7d4`.`tag_id` IN
  (SELECT `tags`.`id`
   FROM `tags`
   WHERE LOWER(`tags`.`name`) LIKE 'end))' ESCAPE '!')
WHERE `events`.`moderated` = 1
  AND ('2019-07-29' <= end_time
       AND start_time <= '2019-09-01 23:59:59.999999')
ORDER BY id DESC
LIMIT 3000

#13

Mis à jour par Christian P. Momon il y a plus de 4 ans

  • Statut changé de Attente d'information à En cours de traitement

Un indice important, c'est le type de ces requêtes qui n'en finissent pas : statistics.

Après une recherche web : https://stackoverflow.com/questions/17797191/sql-query-stuck-in-statistics-state

*SQL Query Stuck in Statistics State*
I've been troubleshooting this complex query today, thinking it was a performance issue. It appears that the query is getting stuck into the 'Statistics' state. It is currently in that state for 1300 seconds.
[…]
I ran into the same problem recently: MySQL started to choke (stuck in state 'statistics') on queries with a lot of tables joined together. I found a good blog post explaining why this happens and how to solve it.
Basically at least in MySQL 5.5, the default value for the configuration parameter optimizer_search_depth is 62 which will cause the query optimizer to take exponentially more time as the number of tables in the query increases. After a certain point it will start to take days or even longer to finish the query.
However, if you set the optimizer_search_depth to 0 in your my.cnf, MySQL automatically chooses suitable depth, but limits it to 7 which is not yet too complex.
Apparently this issue has been fixed in MySQL 5.6 but I haven't tested it myself yet.

Voilà une explication intéressante. Vérifions notre paramétrage :

MariaDB [adl_fr]> SHOW global VARIABLES LIKE '%optimizer_search_depth%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| optimizer_search_depth | 62    |
+------------------------+-------+

Et notre version de Mysql :

(April) root@adl:~/Cpm# dpkg -l mysql-server
ii  mysql-server                                                5.5.9999+default                   amd64                              MySQL database server binaries and system database setup [transitional]

Nous pouvons en déduire ce qu'il se passe :
  • des statistiques sont démarrées sur une grosse requête pleine de JOIN ;
  • comme le paramètre optimizer_search_depth a pour valeur 62, l'analyse statistique peut prendre des jours ;
  • comme le nombre de Thread connecté est de 3, ça sature très vite ;
  • et donc le mysql est très occupé (gros top) et n'est plus disponible pour répondre aux requêtes.
Suggestions :
  • mettre optimizer_search_depth à 0 ;
  • migrer en Buster avec MariaDB 10.3 ;
  • augmenter le nombre de requêtes traitables en même temps : 3 semble ridicule.
#14

Mis à jour par Christian P. Momon il y a plus de 4 ans

  • Statut changé de En cours de traitement à Résolu

Dans root@adl:/etc/mysql/mariadb.conf.d/50-server.cnf, ajout de :

# Cpm 13/09/2019 stop hugly statistics queries (#3773).
optimizer_search_depth  = 0

Vérification :

MariaDB [adl_fr]> SHOW global VARIABLES LIKE '%optimizer_search_depth%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| optimizer_search_depth | 0     |
+------------------------+-------+

#15

Mis à jour par Quentin Gibeaux il y a plus de 4 ans

  • Statut changé de Résolu à Fermé

Formats disponibles : Atom PDF