Project

General

Profile

Anomalie #1176

redmine est a 100% de CPU depuis plusieurs heures

Added by Loïc Dachary almost 9 years ago. Updated over 2 years ago.

Status:
Fermé
Priority:
Immédiate
Assignee:
Category:
Task
Target version:
Start date:
Due date:
% Done:

100%

Estimated time:
Spent time:
Difficulté:
2 Facile

Description

Hypothèse : il y a une URL dans redmine qui provoque un bug qui conduit à une boucle d'allocation infinie:

# strace -p 29712
Process 29712 attached - interrupt to quit
brk(0x505e9000)                         = 0x505e9000
brk(0x505e7000)                         = 0x505e7000
brk(0x50608000)                         = 0x50608000
brk(0x50606000)                         = 0x50606000
...

et donc un process qui utilise de plus en plus de RAM et 100% d'un CPU.

ssh -t -A root@pavot.april.org vserver amphetamine enter # redmine

29712 www-data  20   0 1047m 882m 2692 R  101  3.7 242:44.56 Rails: /usr/share/redmine

C'est arrivé au moment ou google a décidé de crawl tout le site. Il parait difficile de trouver quelle requete exactement a déclenché ce comportement. Les logs ne montrent pas d'erreurs portant sur une requete ayant duré plusieurs heures:

grep '^Completed' /var/log/redmine/default/production.log | grep -v '200 OK' 

et la granularité de munin ne permet pas de situer l'apparition du comportement de façon précise : il y a des centaines de requetes qui ont été faites entre 6am et 7am le 27 janvier 2013 ( voir les logs attaché au ticket )


Files

redmine.png (22.8 KB) redmine.png Loïc Dachary, 01/27/2013 10:30 AM
production.log.1.gz (404 KB) production.log.1.gz logs de prodution correspondant a la période d'apparition du problème Loïc Dachary, 01/27/2013 01:04 PM
production.log.gz (164 KB) production.log.gz logs de prodution correspondant a la période d'apparition du problème ( apres 6:25) Loïc Dachary, 01/27/2013 01:06 PM

Related issues

Related to Admins - Anomalie #1178: surveiller la consomation CPU de agir.april.orgFermé01/27/2013

Actions
Related to Admins - Anomalie #1179: agir.april.org out of memoryFermé01/31/2013

Actions
Related to Admins - Anomalie #1234: oom killer sur pavotFermé03/14/201303/16/2013

Actions

History

#1

Updated by Loïc Dachary almost 9 years ago

  • File deleted (signature.asc)
#2

Updated by Loïc Dachary almost 9 years ago

  • Category set to Task
  • Status changed from Nouveau to Confirmé
  • Assignee set to Loïc Dachary
  • Priority changed from Normale to Immédiate
  • Target version set to Janvier 2013
#3

Updated by Loïc Dachary almost 9 years ago

 tail -f /var/log/redmine/default/production.log

Processing IssuesController#index (for 66.249.76.56 at 2013-01-27 10:32:20) [GET]
  Parameters: {"action"=>"index", "page"=>"3", "controller"=>"issues", "per_page"=>"xmsqozgry", "sort"=>"priority,assigned_to,tracker"}
Rendering template within layouts/base
Rendering issues/index.rhtml
Completed in 378ms (View: 118, DB: 46) | 200 OK [https://agir.april.org/issues?page=3&per_page=xmsqozgry&sort=priority%2Cassigned_to%2Ctracker]

Processing TimelogController#details (for 66.249.76.56 at 2013-01-27 10:32:32) [GET]
  Parameters: {"project_id"=>"admins", "action"=>"details", "page"=>"11", "controller"=>"timelog", "per_page"=>"100", "sort"=>"project,spent_on:desc,issue:desc"}
Rendering template within layouts/base
Rendering timelog/details
Completed in 583ms (View: 366, DB: 28) | 200 OK [https://agir.april.org/projects/admins/time_entries?page=11&per_page=100&sort=project%2Cspent_on%3Adesc%2Cissue%3Adesc]

Processing ProjectsController#activity (for 66.249.76.56 at 2013-01-27 10:32:33) [GET]
  Parameters: {"show_documents"=>"1", "from"=>"2012-10-24", "action"=>"activity", "id"=>"aprilcamp", "controller"=>"projects"}
Rendering template within layouts/base
Rendering projects/activity
Completed in 60ms (View: 33, DB: 7) | 200 OK [https://agir.april.org/projects/aprilcamp/activity?from=2012-10-24&show_documents=1]
#4

Updated by Loïc Dachary almost 9 years ago

On dirait bien que c'est google qui crawl.

# host 66.249.76.56
56.76.249.66.in-addr.arpa domain name pointer crawl-66-249-76-56.googlebot.com.

#5

Updated by Loïc Dachary almost 9 years ago

  • Subject changed from redmine est a 100% de CPU to redmine est a 100% de CPU depuis plusieurs heures
#6

Updated by Loïc Dachary almost 9 years ago

apache2 stop et il reste un process ruby qui prend 100% de la CPU

root@amphetamine:/# strace -p 29712
Process 29712 attached - interrupt to quit
brk(0x505e9000)                         = 0x505e9000
brk(0x505e7000)                         = 0x505e7000
brk(0x50608000)                         = 0x50608000
brk(0x50606000)                         = 0x50606000
brk(0x50627000)                         = 0x50627000
brk(0x50625000)                         = 0x50625000
brk(0x50646000)                         = 0x50646000
brk(0x50644000)                         = 0x50644000
brk(0x50665000)                         = 0x50665000
brk(0x50663000)                         = 0x50663000
brk(0x50684000)                         = 0x50684000
brk(0x50682000)                         = 0x50682000
brk(0x506a3000)                         = 0x506a3000
brk(0x506a1000)                         = 0x506a1000
brk(0x506c2000)                         = 0x506c2000
brk(0x506c0000)                         = 0x506c0000
brk(0x506e1000)                         = 0x506e1000
...

Je le kill -15 et je relance apache

#7

Updated by Loïc Dachary almost 9 years ago

Les requetes google ne pouvaient pas générer cette consomation CPU : les logs disent qu'elle prennent au plus 500ms et les requetes google se font a plusieurs secondes d'intervalle. Donc ça ne peut pas manger 100% d'un cpu.

#10

Updated by Loïc Dachary almost 9 years ago

  • Status changed from Confirmé to Résolu
  • % Done changed from 0 to 100

la remonté d'alerte se fait via munin-node qui est installé sur amphetamine et qui préviendra la prochaine fois que cela se produit

#11

Updated by Quentin Gibeaux over 2 years ago

  • Status changed from Résolu to Fermé

Also available in: Atom PDF