Actions
Demande #3773
ferméAugmenter les ressources de la VM adl
Ajouté par Christian P. Momon il y a environ 5 ans. Mis à jour il y a presque 5 ans.
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 |
Actions
#1
Mis à jour par Christian P. Momon il y a environ 5 ans
Configuration actuelle :
- MemTotal: 2 052 448 kB ;
- CPU : 1.
Actions
#2
Mis à jour par Christian P. Momon il y a environ 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.
Actions
#3
Mis à jour par Christian P. Momon il y a environ 5 ans
- Lié à Demande #3551: Configurer nginx@bastion pour limiter les requêtes ajouté
Actions
#4
Mis à jour par Christian P. Momon il y a environ 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.
Actions
#5
Mis à jour par Christian P. Momon il y a environ 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 ?
Actions
#6
Mis à jour par Christian P. Momon il y a environ 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
Actions
#7
Mis à jour par Christian P. Momon il y a environ 5 ans
- Version cible changé de Backlog à Été 2019
Actions
#8
Mis à jour par Christian P. Momon il y a environ 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
Actions
#9
Mis à jour par Christian P. Momon il y a presque 5 ans
- Fichier slow_query-20190721.log slow_query-20190721.log ajouté
Suite à la configuration de log supplémentaires, analyse du fichier slow_query.log.
Rien vu de spécial.
Actions
#10
Mis à jour par Christian P. Momon il y a presque 5 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
Actions
#11
Mis à jour par Christian P. Momon il y a presque 5 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.
Actions
#12
Mis à jour par Christian P. Momon il y a presque 5 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®ion=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®ion=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®ion=1 HTTP/1.1", upstream: "http://172.16.0.10:80/events.rss?near%5Blocation%5D=strasbourg&near%5Bdistance%5D=50®ion=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
Actions
#13
Mis à jour par Christian P. Momon il y a presque 5 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.
- 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.
Actions
#14
Mis à jour par Christian P. Momon il y a presque 5 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 | +------------------------+-------+
Actions