processus dans l'état D à tuer

Le
Francois Lafont
Bonjour à tous,

J'ai souci qui me semble impossible à résoudre autrement qu'en
redémarrant le système ce que j'aimerais vraiment éviter.

Voilà, suite à des backups qui ont mal tourné, je me retrouve
avec des processus en stand-by dans l'état D :

~# ps -u root -o 'pid,ppid,command' | grep dum[p]
2272 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
2354 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
3050 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
5989 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
6269 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
6376 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
9356 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
9463 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
11429 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
12563 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
13538 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
15030 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
16300 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
16961 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
18474 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
20029 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
22113 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
23912 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
24004 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
24690 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
27731 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone
31540 1 /sbin/dump -f - /dev/vg1/blogs-2-disk-clone

Le dump envoie sa sortie vers gzip à travers un pipe. Impossible
de tuer ces processus même avec kill -KILL. Si j'ai bien compris,
c'est normal car ils sont en attente au niveau I/O, état qui
est censé durer très peu de temps et pendant lequel un processus
ne fait strictement rien à part attendre et il n'écoute aucun
signal (et mes kill n'aboutissent pas).

Ok. Il faut donc que je dégage le volume logique blogs-2-disk-clone
(qui est un volume temporaire en principe donc pas de souci s'il
faut le zigouiller). Du coup, je tente :

~# lvremove -f /dev/vg1/blogs-2-disk-clone
Can't remove open logical volume "blogs-2-disk-clone"

~# lvchange --ignorelockingfailure -an /dev/vg1/blogs-2-disk-clone
Can't change snapshot logical volume "blogs-2-disk-clone"

C'est logique, il me dit que mon lv est ouvert etc. alors
impossible de le zigouiller.

Du coup, j'ai un peu l'impression que c'est la quadrature du
cercle ce machin avec d'un côté des processus dans l'attente d'un
device en continu et de l'autre un device que je ne peux pas
virer car il me dit qu'il est ouvert pas des processus.

Y a-t-il un moyen d'éviter le reboot du système ?
(j'aimerais bien ;-))

Merci pour votre aide.

PS : oui le processus parent des commandes dump est init,
mais ce n'était pas le cas au départ et c'est peut-être là
où j'ai merdé. Lorsque j'ai tué le processus initial (ie le
script qui lance les backups) j'ai fait un :

kill -TERM <LE-PID-SCRIPT>

alors que j'aurais sûrement dû faire :

kill -TERM -<LE-PID-SCRIPT> # avec un « - » devant le pid

car ça aurait tué tout le groupe et ça m'aurait évité mon
problème actuel. Je me trompe ?


--
François Lafont
Vidéos High-Tech et Jeu Vidéo
Téléchargements
Vos réponses Page 1 / 2
Gagnez chaque mois un abonnement Premium avec GNT : Inscrivez-vous !
Trier par : date / pertinence
Francois Lafont
Le #25752872
Bonsoir,

D'après ce que je lis sur le Web :

1) je n'ai aucune chance de killer des processus dans l'état D.

2) Ma seule chance est d'arriver à supprimer le volume logique
que mes dumps tentent de lire en vain. Mais là aussi rien à faire :

~# lvremove -f /dev/vg1/blogs-2-disk-clone
Can't remove open logical volume "blogs-2-disk-clone"

~# dmsetup remove --force $(readlink -f /dev/vg1/blogs-2-disk-clone)
device-mapper: remove ioctl failed: Périphérique ou ressource occupé
Command failed

Pouvez-vous me confirmer (ou pas ;-)) que je n'ai pas d'autre choix
que le reboot ?

--
François Lafont
Kevin Denis
Le #25752892
Le 31-10-2013, Francois Lafont
Pouvez-vous me confirmer (ou pas ;-)) que je n'ai pas d'autre choix
que le reboot ?



De par mon expérience, oui. J'avais eu le cas avec un CD, et le même
problème de process en état D.
Seule solution efficace: reboot.
--
Kevin
Francois Lafont
Le #25753722
Le 31/10/2013 06:19, Kevin Denis a écrit :
Le 31-10-2013, Francois Lafont
Pouvez-vous me confirmer (ou pas ;-)) que je n'ai pas d'autre choix
que le reboot ?



De par mon expérience, oui. J'avais eu le cas avec un CD, et le même
problème de process en état D.
Seule solution efficace: reboot.



Ok, merci de ta réponse.

C'est quand même fou qu'il existe un état (l'état D donc) dans lequel un
processus ne réagisse à aucun signal envoyé par kill. Ça devrait pas
exister un machin comme ça. ;-)

Perso, j'ai déjà vu des processus dans l'état D finir par disparaître
mais ça passait par la destruction du device responsable du « blocage ».
Ici, impossible de le flinguer ce device (le volume logique LVM).

Ah... tant pis, je me fendrai d'un reboot alors.

--
François Lafont
JKB
Le #25753882
Le Thu, 31 Oct 2013 12:53:23 +0100,
Francois Lafont
Le 31/10/2013 06:19, Kevin Denis a écrit :
Le 31-10-2013, Francois Lafont
Pouvez-vous me confirmer (ou pas ;-)) que je n'ai pas d'autre choix
que le reboot ?



De par mon expérience, oui. J'avais eu le cas avec un CD, et le même
problème de process en état D.
Seule solution efficace: reboot.



Ok, merci de ta réponse.

C'est quand même fou qu'il existe un état (l'état D donc) dans lequel un
processus ne réagisse à aucun signal envoyé par kill. Ça devrait pas
exister un machin comme ça. ;-)

Perso, j'ai déjà vu des processus dans l'état D finir par disparaître
mais ça passait par la destruction du device responsable du « blocage ».
Ici, impossible de le flinguer ce device (le volume logique LVM).

Ah... tant pis, je me fendrai d'un reboot alors.




Ça me semble bizarre, ton histoire. À chaque fois que j'ai vu des
processus dans l'état D, il y avait de bonnes raisons à cela (style
I/O sur un périphérique qui ne répond plus). Ne faudrait-il pas
plutôt regarder du côté des sources du problème ? L'état D n'est
qu'une conséquence.

Cordialement,

JKB

--
Si votre demande me parvient sur carte perforée, je titiouaillerai très
volontiers une réponse...
=> http://grincheux.de-charybde-en-scylla.fr
=> http://loubardes.de-charybde-en-scylla.fr
Francois Lafont
Le #25754092
Le 31/10/2013 13:46, JKB a écrit :

Ça me semble bizarre, ton histoire. À chaque fois que j'ai vu des
processus dans l'état D, il y avait de bonnes raisons à cela (style
I/O sur un périphérique qui ne répond plus).



Et c'est bien le cas ici. J'ai un lv (logical volume) qui ne répond plus.
Mais impossible de le supprimer celui-là malheureusement.

Ne faudrait-il pas
plutôt regarder du côté des sources du problème ? L'état D n'est
qu'une conséquence.



Sans doute. Personnellement je n'ai pas trop d'idée, mais je peux fournir
quelques éléments ci-dessous.

Ça se passe sur un serveur Xen où les disques des VMs sont des lv.
Tous les soirs à 1h00, pour chaque VM, un snapshot du lv
(logical volume) du disque est fait. Par exemple :

lvcreate --snapshot -L6272M -n blogs-2-disk-clone /dev/vg1/blogs-2-disk

et un dump de ce snapshot est fait :

dump -f - /dev/vg1/blogs-2-disk-clone | gzip > $BACKUP_PATH/blogs-2-disk-clone.dump.gz

Et quand c'est fini, le snapshot est détruit :

lvremove -f /dev/vg1/blogs-2-disk-clone

Ce cron fonctionnait bien a priori depuis pas mal de temps. Pour des
raisons que j'ignore un jour ça a bloqué au niveau du dump sur le snapshot
mais je ne m'en suis pas rendu compte tout de suite. Ensuite, au fur et à
mesure que les crons se sont succédés, des processus dans l'état D
(ceux associés à la commande dump) se sont accumulés et là je me
suis aperçu du problème.

Dans un premier temps, je voudrais nettoyer un peu tout ça, ie tuer
les processus et virer le lv /dev/vg1/blogs-2-disk-clone. Encore une
fois, le cron fonctionnait très bien depuis fort longtemps et donc
ceci me laisse penser que le blocage initial est un « impondérable ».
Maintenant, une fois la situation remise « à zéro », je n'ai pas la
certitude non plus que le cron va à nouveau fonctionner correctement
comme avant.

--
François Lafont
JKB
Le #25754072
Le Thu, 31 Oct 2013 14:23:17 +0100,
Francois Lafont
Le 31/10/2013 13:46, JKB a écrit :

Ça me semble bizarre, ton histoire. À chaque fois que j'ai vu des
processus dans l'état D, il y avait de bonnes raisons à cela (style
I/O sur un périphérique qui ne répond plus).



Et c'est bien le cas ici. J'ai un lv (logical volume) qui ne répond plus.
Mais impossible de le supprimer celui-là malheureusement.



S'il ne répond plus, il doit y avoir un message quelque par dans les
logs qui explique pourquoi il ne répond plus.

Ne faudrait-il pas
plutôt regarder du côté des sources du problème ? L'état D n'est
qu'une conséquence.



Sans doute. Personnellement je n'ai pas trop d'idée, mais je peux fournir
quelques éléments ci-dessous.

Ça se passe sur un serveur Xen où les disques des VMs sont des lv.
Tous les soirs à 1h00, pour chaque VM, un snapshot du lv
(logical volume) du disque est fait. Par exemple :

lvcreate --snapshot -L6272M -n blogs-2-disk-clone /dev/vg1/blogs-2-disk

et un dump de ce snapshot est fait :

dump -f - /dev/vg1/blogs-2-disk-clone | gzip > $BACKUP_PATH/blogs-2-disk-clone.dump.gz

Et quand c'est fini, le snapshot est détruit :

lvremove -f /dev/vg1/blogs-2-disk-clone

Ce cron fonctionnait bien a priori depuis pas mal de temps. Pour des
raisons que j'ignore un jour ça a bloqué au niveau du dump sur le snapshot
mais je ne m'en suis pas rendu compte tout de suite. Ensuite, au fur et à
mesure que les crons se sont succédés, des processus dans l'état D
(ceux associés à la commande dump) se sont accumulés et là je me
suis aperçu du problème.

Dans un premier temps, je voudrais nettoyer un peu tout ça, ie tuer
les processus et virer le lv /dev/vg1/blogs-2-disk-clone. Encore une
fois, le cron fonctionnait très bien depuis fort longtemps et donc
ceci me laisse penser que le blocage initial est un « impondérable ».



Ça pourrait être une tentative de démontage sauvage de
/dev/vg1/blogs-2-disk-clone ou un script tellement long que celui de
la veille n'est pas terminé lorsque celui du jour reprend.

Je commencerais par mettre un mutex sur la chose. Soit à l'ancienne
(avec un touch lock) si le script n'est lancé que par un seul cron,
soit un vrai mutex POSIX.

Maintenant, une fois la situation remise « à zéro », je n'ai pas la
certitude non plus que le cron va à nouveau fonctionner correctement
comme avant.



Cordialement,

JKB

--
Si votre demande me parvient sur carte perforée, je titiouaillerai très
volontiers une réponse...
=> http://grincheux.de-charybde-en-scylla.fr
=> http://loubardes.de-charybde-en-scylla.fr
Francois Lafont
Le #25754202
Le 31/10/2013 14:32, JKB a écrit :

Et c'est bien le cas ici. J'ai un lv (logical volume) qui ne répond plus.
Mais impossible de le supprimer celui-là malheureusement.



S'il ne répond plus, il doit y avoir un message quelque par dans les
logs qui explique pourquoi il ne répond plus.



Le blocage initial a eu lieu le 8 ou le 9 octobre (j'ai un petit doute).
J'ai rien dans syslog qui remonte aussi loin et en fait j'ai même absolument
rien dans syslog sur ce problème de device même pour les crons plus récents.

Après j'ai ça :

~# zcat /var/log/kern.log.3.gz
Oct 6 06:25:41 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 7 02:14:50 wopr-2 kernel: [8215834.068403] o2net: no longer connected to node wopr-3 (num 2) at 172.30.253.3:17777
Oct 7 02:14:50 wopr-2 kernel: [8215834.068498] (3667,0):o2dlm_eviction_cb:258 o2dlm has evicted node 2 from group 7518F1B8125F41E2AB067363BE0E0F40
Oct 7 02:14:51 wopr-2 kernel: [8215835.129481] (3655,0):o2dlm_eviction_cb:258 o2dlm has evicted node 2 from group 7518F1B8125F41E2AB067363BE0E0F40
Oct 7 02:17:23 wopr-2 kernel: [8215988.244509] o2net: accepted connection from node wopr-3 (num 2) at 172.30.253.3:17777
Oct 7 02:17:23 wopr-2 kernel: [8215988.245747] ocfs2_dlm: Node 2 joins domain 7518F1B8125F41E2AB067363BE0E0F40
Oct 7 02:17:23 wopr-2 kernel: [8215988.245782] ocfs2_dlm: Nodes in domain ("7518F1B8125F41E2AB067363BE0E0F40"): 0 1 2 3 4
Oct 7 06:25:09 wopr-2 kernel: Kernel logging (proc) stopped.
Oct 7 06:25:09 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 8 06:25:10 wopr-2 kernel: Kernel logging (proc) stopped.
Oct 8 06:25:10 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 8 21:14:53 wopr-2 kernel: [8371741.834182] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
Oct 8 21:14:53 wopr-2 kernel: [8371741.834664] NFSD: starting 90-second grace period
Oct 8 21:14:55 wopr-2 kernel: [8371743.743300] nfsd: last server has exited
Oct 8 21:14:55 wopr-2 kernel: [8371743.743336] nfsd: unexporting all filesystems
Oct 8 21:21:46 wopr-2 kernel: [8372157.876402] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
Oct 8 21:21:46 wopr-2 kernel: [8372157.876489] NFSD: starting 90-second grace period
Oct 8 21:21:53 wopr-2 kernel: [8372164.501710] nfsd: last server has exited
Oct 8 21:21:53 wopr-2 kernel: [8372164.501710] nfsd: unexporting all filesystems
Oct 8 21:45:37 wopr-2 kernel: [8373598.095564] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
Oct 8 21:45:37 wopr-2 kernel: [8373598.095564] NFSD: starting 90-second grace period
Oct 8 21:45:44 wopr-2 kernel: [8373605.246855] nfsd: last server has exited
Oct 8 21:45:44 wopr-2 kernel: [8373605.246892] nfsd: unexporting all filesystems
Oct 8 21:54:10 wopr-2 kernel: [8374115.152777] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
Oct 8 21:54:10 wopr-2 kernel: [8374115.152859] NFSD: starting 90-second grace period
Oct 8 21:54:12 wopr-2 kernel: [8374116.993264] nfsd: last server has exited
Oct 8 21:54:12 wopr-2 kernel: [8374116.993264] nfsd: unexporting all filesystems
Oct 8 21:57:03 wopr-2 kernel: [8374289.955048] ------------[ cut here ]------------
Oct 8 21:57:03 wopr-2 kernel: [8374289.955088] kernel BUG at include/linux/module.h:386!
Oct 8 21:57:03 wopr-2 kernel: [8374289.955119] invalid opcode: 0000 [1] SMP
Oct 8 21:57:03 wopr-2 kernel: [8374289.955154] CPU 7
Oct 8 21:57:03 wopr-2 kernel: [8374289.955181] Modules linked in: xt_physdev iptable_filter ip_tables x_tables ocfs2 ocfs2_dlmfs ocfs2_stack_o2cb ocfs2_dlm ocfs2_nodemanager ocfs2_stackglue configfs nfsd auth_rpcgss exportfs nfs lockd nfs_acl sunrpc ipv6 bridge loop psmouse i2c_i801 serio_raw rng_core pcspkr i2c_core i5000_edac container shpchp button edac_core pci_hotplug evdev ext3 jbd mbcache dm_mirror dm_log dm_snapshot dm_mod ide_cd_mod cdrom ses enclosure piix ide_pci_generic ide_core usbhid hid ff_memless sd_mod floppy ata_generic qla2xxx e1000 firmware_class libata dock scsi_transport_fc ehci_hcd 3w_9xxx scsi_tgt uhci_hcd scsi_mod e1000e thermal processor fan thermal_sys [last unloaded: scsi_wait_scan]
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] Pid: 17517, comm: mount Not tainted 2.6.26-2-xen-amd64 #1
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] RIP: e030:[<ffffffff8029f9d1>] [<ffffffff8029f9d1>] get_filesystem+0x16/0x32
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] RSP: e02b:ffff88007add5d08 EFLAGS: 00010246
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] RAX: 0000000000000000 RBX: ffffffffa02d9700 RCX: ffffffffa02d91f0
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] RDX: 0000000000001000 RSI: ffffffffa02c5c08 RDI: ffffffffa02d9700
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] RBP: ffff8800b927c800 R08: ffff8800b927ca68 R09: ffff88007add5c48
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] R10: ffff8800529c8000 R11: ffffffff802e5f9e R12: 0000000000000000
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] R13: ffffffffa02d91c0 R14: 0000000000000000 R15: ffffffff8028bb30
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] FS: 00007f9d390927c0(0000) GS:ffffffff8053a380(0000) knlGS:0000000000000000
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] CS: e033 DS: 0000 ES: 0000
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] Process mount (pid: 17517, threadinfo ffff88007add4000, task ffff8800502da780)
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] Stack: ffff8800b927c800 ffffffff8028c1e9 ffffffff8028cf56 ffff8803e8c31680
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] 0000000000000000 0000000000000000 0000000000000000 ffffffffa02bef77
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] ffff8803e8c31680 ffffffff8028caf9 ffff8800529c8000 ffff8803e8c31680
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] Call Trace:
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff8028c1e9>] ? sget+0x436/0x445
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff8028cf56>] ? set_anon_super+0x0/0xee
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffffa02bef77>] ? :sunrpc:rpc_fill_super+0x0/0x9b
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff8028caf9>] ? get_sb_single+0x2f/0xb3
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff8028c773>] ? vfs_kern_mount+0x93/0x11b
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff8028c84e>] ? do_kern_mount+0x43/0xe3
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff802a2b31>] ? do_new_mount+0x5b/0x95
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff802a2d28>] ? do_mount+0x1bd/0x1e7
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff80269756>] ? __alloc_pages_internal+0xd6/0x3b2
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff802a2ddc>] ? sys_mount+0x8a/0xce
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff8020b528>] ? system_call+0x68/0x6d
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] [<ffffffff8020b4c0>] ? system_call+0x0/0x6d
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525]
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525]
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] Code: d6 03 27 00 eb 05 bb ea ff ff ff 59 5e 48 63 c3 5b 5d 41 5c c3 53 48 8b 5f 20 48 85 db 74 26 48 89 df e8 9e 9e fa ff 85 c0 75 04 <0f> 0b eb fe 65 8b 04 25 24 00 00 00 89 c0 48 c1 e0 07 48 ff 84
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] RIP [<ffffffff8029f9d1>] get_filesystem+0x16/0x32
Oct 8 21:57:03 wopr-2 kernel: [8374289.956525] RSP <ffff88007add5d08>
Oct 8 21:57:03 wopr-2 kernel: [8374289.958887] ---[ end trace 18c6f60450ad0744 ]---
Oct 8 21:57:03 wopr-2 kernel: [8374290.096313] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
Oct 8 21:57:03 wopr-2 kernel: [8374290.096482] NFSD: starting 90-second grace period
Oct 8 21:57:11 wopr-2 kernel: [8374297.639761] nfsd: last server has exited
Oct 8 21:57:11 wopr-2 kernel: [8374297.639761] nfsd: unexporting all filesystems
Oct 9 06:25:03 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 9 06:25:03 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 10 06:25:02 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 11 06:25:01 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 12 06:25:01 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 13 06:25:10 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.

Je précise que la machine est un Xen sous Lenny, pas un truc super à jour
donc.

Voici des logs plus récents.

~# cat /var/log/kern.log
Oct 27 06:25:03 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 28 06:25:01 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 29 06:25:01 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 29 19:22:23 wopr-2 kernel: [10187384.549824] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 29 19:23:04 wopr-2 kernel: [10187426.210236] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 29 19:26:35 wopr-2 kernel: [10187638.315182] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 30 00:04:41 wopr-2 kernel: [10204363.107830] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 30 00:07:22 wopr-2 kernel: [10204525.047532] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 30 00:08:57 wopr-2 kernel: [10204619.592177] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 30 00:36:01 wopr-2 kernel: [10206248.646601] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 30 00:38:04 wopr-2 kernel: [10206371.205929] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 30 01:00:02 wopr-2 kernel: [10207692.881193] Buffer I/O error on device dm-20, logical block 0
Oct 30 01:00:02 wopr-2 kernel: [10207692.881239] Buffer I/O error on device dm-20, logical block 1
Oct 30 01:00:02 wopr-2 kernel: [10207692.881273] Buffer I/O error on device dm-20, logical block 2
Oct 30 01:00:02 wopr-2 kernel: [10207692.881307] Buffer I/O error on device dm-20, logical block 3
Oct 30 01:00:02 wopr-2 kernel: [10207692.881341] Buffer I/O error on device dm-20, logical block 0
Oct 30 06:25:01 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 31 01:00:01 wopr-2 kernel: [10294298.195608] Buffer I/O error on device dm-20, logical block 0
Oct 31 01:00:01 wopr-2 kernel: [10294298.195608] Buffer I/O error on device dm-20, logical block 1
Oct 31 01:00:01 wopr-2 kernel: [10294298.195608] Buffer I/O error on device dm-20, logical block 2
Oct 31 01:00:01 wopr-2 kernel: [10294298.195608] Buffer I/O error on device dm-20, logical block 3
Oct 31 01:00:01 wopr-2 kernel: [10294298.195608] Buffer I/O error on device dm-20, logical block 0
Oct 31 01:31:17 wopr-2 kernel: [10296178.409439] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 31 01:31:36 wopr-2 kernel: [10296197.632818] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 31 01:33:10 wopr-2 kernel: [10296291.173904] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 31 06:25:03 wopr-2 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Oct 31 14:55:26 wopr-2 kernel: [10344536.186646] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 31 14:56:11 wopr-2 kernel: [10344581.056024] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 31 14:58:58 wopr-2 kernel: [10344749.028319] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 31 14:59:09 wopr-2 kernel: [10344759.097202] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone
Oct 31 14:59:43 wopr-2 kernel: [10344794.171146] device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone

Les « device-mapper: ioctl: unable to remove open device vg1-blogs--2--disk--clone »
ce sont mes tentatives désepérées pour virer ce lv avec :

dmsetup remove --force $(readlink -f /dev/vg1/blogs-2-disk-clone)

Pour le reste, même si je vois bien qu'il y a un souci, je ne sais pas quoi
faire.

C'est dommage parce que, quand on lit la page man, la commande ci-dessus
semble être exactement ce qu'il me faut :

remove [-f|--force] device_name
Removes a device. It will no longer be visible to dmsetup.
Open devices cannot be removed except with older kernels that
contain a version of device-map‐per prior to 4.8.0. In this case
the device will be deleted when its open_count drops to zero.
From version 4.8.0 onwards, if a device can’t be removed because
an uninterruptible process is waiting for I/O to return from it,
adding --force will replace the table with one that fails all I/O,
which might allow the process to be killed.

Voici d'autres éléments pour info :

~# ps -u root -o 'state,pid,ppid,command,start' | grep dum[p]
D 1100 1 /sbin/dump -f - /dev/vg1/bl Oct 29
D 2272 1 /sbin/dump -f - /dev/vg1/bl Oct 19
D 2354 1 /sbin/dump -f - /dev/vg1/bl Oct 28
D 3050 1 /sbin/dump -f - /dev/vg1/bl Oct 20
D 5989 1 /sbin/dump -f - /dev/vg1/bl Oct 29
D 6269 1 /sbin/dump -f - /dev/vg1/bl Oct 09
D 6376 1 /sbin/dump -f - /dev/vg1/bl Oct 21
D 9356 1 /sbin/dump -f - /dev/vg1/bl Oct 10
D 9463 1 /sbin/dump -f - /dev/vg1/bl Oct 22
D 10139 1 /sbin/dump -f - /dev/vg1/fp Oct 30
D 11429 1 /sbin/dump -f - /dev/vg1/bl Oct 23
D 12563 1 /sbin/dump -f - /dev/vg1/bl Oct 11
D 13538 1 /sbin/dump -f - /dev/vg1/bl Oct 29
D 13796 1 /sbin/dump -f - /dev/vg1/fp 01:00:02
D 15030 1 /sbin/dump -f - /dev/vg1/bl Oct 24
D 16300 1 /sbin/dump -f - /dev/vg1/bl Oct 12
D 16961 1 /sbin/dump -f - /dev/vg1/bl Oct 13
D 18474 1 /sbin/dump -f - /dev/vg1/bl Oct 25
D 20029 1 /sbin/dump -f - /dev/vg1/bl Oct 14
D 22113 1 /sbin/dump -f - /dev/vg1/bl Oct 26
D 23912 1 /sbin/dump -f - /dev/vg1/bl Oct 15
D 24004 1 /sbin/dump -f - /dev/vg1/bl Oct 27
D 24690 1 /sbin/dump -f - /dev/vg1/bl Oct 16
D 27731 1 /sbin/dump -f - /dev/vg1/bl Oct 17
D 31540 1 /sbin/dump -f - /dev/vg1/bl Oct 18

~# lsof /dev/vg1/blogs-2-disk-clone
COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
dump 1100 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 1100 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 2272 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 2272 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 2354 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 2354 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 3050 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 3050 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 5989 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 5989 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 6269 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 6269 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 6376 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 6376 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 9356 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 9356 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 9463 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 9463 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 11429 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 11429 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 12563 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 12563 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 13538 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 13538 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 15030 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 15030 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 16300 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 16300 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 16961 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 16961 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 18474 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 18474 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 20029 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 20029 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 22113 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 22113 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 23912 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 23912 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 24004 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 24004 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 24690 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 24690 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 27731 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 27731 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 31540 root 3r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone
dump 31540 root 4r BLK 254,20 66757218 /dev/mapper/vg1-blogs--2--disk--clone

Ça pourrait être une tentative de démontage sauvage de
/dev/vg1/blogs-2-disk-clone ou un script tellement long que celui de
la veille n'est pas terminé lorsque celui du jour reprend.

Je commencerais par mettre un mutex sur la chose. Soit à l'ancienne
(avec un touch lock) si le script n'est lancé que par un seul cron,
soit un vrai mutex POSIX.



C'est vrai que ça serait une amélioration à faire au niveau du cron.

Merci pour ton aide.

--
François Lafont
JKB
Le #25761702
Le Thu, 31 Oct 2013 15:12:08 +0100,
Francois Lafont
Le 31/10/2013 14:32, JKB a écrit :

Et c'est bien le cas ici. J'ai un lv (logical volume) qui ne répond plus.
Mais impossible de le supprimer celui-là malheureusement.



S'il ne répond plus, il doit y avoir un message quelque par dans les
logs qui explique pourquoi il ne répond plus.



Le blocage initial a eu lieu le 8 ou le 9 octobre (j'ai un petit doute).
J'ai rien dans syslog qui remonte aussi loin et en fait j'ai même absolument
rien dans syslog sur ce problème de device même pour les crons plus récents.



Je vois un oops sur un RPC le 8 octobre (avec un invalid opcode 0000).
Ne cherche pas plus loin. Un coup de memtest pour voir l'état de la
mémoire ?

Ça pourrait être une tentative de démontage sauvage de
/dev/vg1/blogs-2-disk-clone ou un script tellement long que celui de
la veille n'est pas terminé lorsque celui du jour reprend.

Je commencerais par mettre un mutex sur la chose. Soit à l'ancienne
(avec un touch lock) si le script n'est lancé que par un seul cron,
soit un vrai mutex POSIX.



C'est vrai que ça serait une amélioration à faire au niveau du cron.



Ça, de toute façon, c'est le minimum ;-)

JKB

--
Si votre demande me parvient sur carte perforée, je titiouaillerai très
volontiers une réponse...
=> http://grincheux.de-charybde-en-scylla.fr
=> http://loubardes.de-charybde-en-scylla.fr
Francois Lafont
Le #25762272
Bonsoir,

Le 04/11/2013 14:05, JKB a écrit :

Le blocage initial a eu lieu le 8 ou le 9 octobre (j'ai un petit doute).
J'ai rien dans syslog qui remonte aussi loin et en fait j'ai même absolument
rien dans syslog sur ce problème de device même pour les crons plus récents.



Je vois un oops sur un RPC le 8 octobre (avec un invalid opcode 0000).
Ne cherche pas plus loin. Un coup de memtest pour voir l'état de la
mémoire ?



J'ai voulu tester sur une VM (en Lenny tout comme le serveur) avec un petit
coup de « apt-get install memtest86+ && update-grub », si j'ai bien compris
ensuite :

1) il faut rebooter le choix memtest86+ via le menu Grub;
2) ça peut prendre un certain temps.

Je n'ai pas un accès physique au serveur (du moins pas facilement) du coup
1) me pose un peu de souci. Certes on a un port IPMI mais il reste ensuite
le point 2) qui me gêne. Est-il possible de mettre en place un memtest86+
un peu light et rapide ?

Je commencerais par mettre un mutex sur la chose. Soit à l'ancienne
(avec un touch lock) si le script n'est lancé que par un seul cron,
soit un vrai mutex POSIX.



C'est vrai que ça serait une amélioration à faire au niveau du cron.



Ça, de toute façon, c'est le minimum ;-)



Ça c'est fait (via la méthode à l'ancienne).

--
François Lafont
JKB
Le #25762442
Le Mon, 04 Nov 2013 23:24:08 +0100,
Francois Lafont
Bonsoir,

Le 04/11/2013 14:05, JKB a écrit :

Le blocage initial a eu lieu le 8 ou le 9 octobre (j'ai un petit doute).
J'ai rien dans syslog qui remonte aussi loin et en fait j'ai même absolument
rien dans syslog sur ce problème de device même pour les crons plus récents.



Je vois un oops sur un RPC le 8 octobre (avec un invalid opcode 0000).
Ne cherche pas plus loin. Un coup de memtest pour voir l'état de la
mémoire ?



J'ai voulu tester sur une VM (en Lenny tout comme le serveur) avec un petit
coup de « apt-get install memtest86+ && update-grub », si j'ai bien compris
ensuite :

1) il faut rebooter le choix memtest86+ via le menu Grub;
2) ça peut prendre un certain temps.



Exact.

Je n'ai pas un accès physique au serveur (du moins pas facilement) du coup
1) me pose un peu de souci. Certes on a un port IPMI mais il reste ensuite
le point 2) qui me gêne. Est-il possible de mettre en place un memtest86+
un peu light et rapide ?



Non. C'est pour cela que les mémoires ECC (et la gestion des
erreurs façon Sun) sont très très bien. Cela permet de voir dans la
plupart des cas la mémoire flancher avant le plantage.

Sinon, il est possible de lancer un memtest en fonctionnement, mais
je ne l'ai jamais trouvé efficace.

Je commencerais par mettre un mutex sur la chose. Soit à l'ancienne
(avec un touch lock) si le script n'est lancé que par un seul cron,
soit un vrai mutex POSIX.



C'est vrai que ça serait une amélioration à faire au niveau du cron.



Ça, de toute façon, c'est le minimum ;-)



Ça c'est fait (via la méthode à l'ancienne).



C'est déjà ça ;-)

JKB

--
Si votre demande me parvient sur carte perforée, je titiouaillerai très
volontiers une réponse...
=> http://grincheux.de-charybde-en-scylla.fr
=> http://loubardes.de-charybde-en-scylla.fr
Publicité
Poster une réponse
Anonyme