2013-07-15 18:27:10

by Philipp Hahn

[permalink] [raw]
Subject: [BUG] 3.10.[01] modprobe snd-... hangs

Hello,

My x86_64 systems has some trouble loading some ALSA snd-* modules since
the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
loading snd-intel-hda and snd-audio-usb by hand still works.

# ps axf
460 ? S 0:00 \_ [kworker/u8:3]
1087 ? S 0:00 | \_ [kworker/u8:3]
1092 ? S 0:00 | \_ /sbin/modprobe -q -- snd-seq-client-14
...
1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq
1115 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd-rawmidi && { /sbin/modprobe --q
1154 ? S 0:00 \_ /sbin/modprobe --quiet snd-seq-midi
1119 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd-rawmidi && { /sbin/modprobe --q
1148 ? S 0:00 \_ /sbin/modprobe --quiet snd-seq-midi

In /var/log/daemon.log I find the following messages:
Jul 15 19:58:44 scout udevd[912]: timeout: killing '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc01ip00in00' [1044]
Jul 15 19:58:56 scout udevd[912]: '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc01ip00in00' [1044] terminated by signal 9 (Killed)
Jul 15 19:58:56 scout udevd[919]: timeout: killing '/sbin/modprobe -b pci:v000010DEd0000026Csv00001462sd00007350bc04sc03i00' [1051]
Jul 15 19:58:56 scout udevd[914]: timeout: killing '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc03ip00in01' [1045]
Jul 15 19:58:56 scout udevd[919]: '/sbin/modprobe -b pci:v000010DEd0000026Csv00001462sd00007350bc04sc03i00' [1051] terminated by signal 9 (Killed)
Jul 15 19:58:56 scout udevd[914]: '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc03ip00in01' [1045] terminated by signal 9 (Killed)


This is a Debian sid system
# modprobe -V
kmod version 9

# echo t >/proc/sysrq-trigger
produces too much output to include the modprobe processes. I already
stopped most processes, but that is not enough.


# cat /proc/1092/syscall
175 0x7effcad92000 0xafe8 0x7effca9c2f88 0x7effca6ea3aa 0x0 0x0 0x7fff3e3de648 0x7effca6eef8a

# cat /proc/1080/syscall
175 0x7fe01b25e000 0xafe8 0x7fe01ae8ef88 0x7fe01abb63aa 0x3 0x0 0x7fffba8cc748 0x7fe01abbaf8a

# cat /proc/1154/syscall
175 0x7fc157a7b000 0xafe8 0x7fc1576abf88 0x7fc1573d33aa 0x3 0x0 0x7fff05809e58 0x7fc1573d7f8a

# cat /proc/1148/syscall
175 0x7fc7159d5000 0xafe8 0x7fc715605f88 0x7fc71532d3aa 0x3 0x0 0x7fff47a1f3c8 0x7fc715331f8a

Is this a know bug or has someone seen similar problems?

# cat /proc/modules
ip6table_filter 1575 0 - Live 0xffffffffa0893000
ip6_tables 13784 1 ip6table_filter, Live 0xffffffffa088b000
ebtable_nat 1887 0 - Live 0xffffffffa0887000
ebtables 19917 1 ebtable_nat, Live 0xffffffffa087e000
snd_usb_audio 124196 0 - Live 0xffffffffa0851000
snd_usbmidi_lib 16982 1 snd_usb_audio, Live 0xffffffffa0848000
rfcomm 28731 10 - Live 0xffffffffa083a000
bnep 9786 2 - Live 0xffffffffa0833000
snd_hda_codec_realtek 37669 1 - Live 0xffffffffa0823000
snd_hda_intel 31432 0 - Live 0xffffffffa0814000
snd_hda_codec 140669 2 snd_hda_codec_realtek,snd_hda_intel, Live 0xffffffffa07e2000
snd_hwdep 5627 2 snd_usb_audio,snd_hda_codec, Live 0xffffffffa07dd000
iptable_filter 1618 1 - Live 0xffffffffa07d9000
xt_owner 1326 1 - Live 0xffffffffa07d5000
ip_tables 13390 1 iptable_filter, Live 0xffffffffa07cd000
x_tables 18433 6 ip6table_filter,ip6_tables,ebtables,iptable_filter,xt_owner,ip_tables, Live 0xffffffffa07c3000
cpufreq_conservative 7015 0 - Live 0xffffffffa07bd000
cpufreq_ondemand 8945 0 - Live 0xffffffffa07b6000
cpufreq_powersave 1010 0 - Live 0xffffffffa07b2000
cpufreq_userspace 2136 0 - Live 0xffffffffa07ae000
binfmt_misc 6479 1 - Live 0xffffffffa07a9000
bridge 74378 0 - Live 0xffffffffa078d000
stp 1908 1 bridge, Live 0xffffffffa0789000
llc 4485 2 bridge,stp, Live 0xffffffffa0784000
deflate 1873 0 - Live 0xffffffffa0780000
ctr 3633 0 - Live 0xffffffffa077c000
twofish_generic 5715 0 - Live 0xffffffffa0777000
twofish_x86_64_3way 19885 0 - Live 0xffffffffa076f000
twofish_x86_64 5503 1 twofish_x86_64_3way, Live 0xffffffffa076a000
twofish_common 13133 3 twofish_generic,twofish_x86_64_3way,twofish_x86_64, Live 0xffffffffa0763000
camellia_generic 18308 0 - Live 0xffffffffa075b000
camellia_x86_64 45885 0 - Live 0xffffffffa074b000
serpent_sse2_x86_64 44963 0 - Live 0xffffffffa073d000
serpent_generic 21243 1 serpent_sse2_x86_64, Live 0xffffffffa0734000
ablk_helper 2284 1 serpent_sse2_x86_64, Live 0xffffffffa0730000
cryptd 7992 1 ablk_helper, Live 0xffffffffa072a000
xts 2958 3 twofish_x86_64_3way,camellia_x86_64,serpent_sse2_x86_64, Live 0xffffffffa0726000
lrw 3584 3 twofish_x86_64_3way,camellia_x86_64,serpent_sse2_x86_64, Live 0xffffffffa0722000
gf128mul 6580 2 xts,lrw, Live 0xffffffffa071d000
glue_helper 4810 3 twofish_x86_64_3way,camellia_x86_64,serpent_sse2_x86_64, Live 0xffffffffa0718000
blowfish_generic 3194 0 - Live 0xffffffffa0714000
blowfish_x86_64 14084 0 - Live 0xffffffffa070d000
blowfish_common 6425 2 blowfish_generic,blowfish_x86_64, Live 0xffffffffa0708000
cast5_generic 10378 0 - Live 0xffffffffa0702000
cast_common 5351 1 cast5_generic, Live 0xffffffffa06fd000
des_generic 16147 0 - Live 0xffffffffa06f6000
cmac 2460 0 - Live 0xffffffffa06f2000
xcbc 2423 0 - Live 0xffffffffa06ee000
rmd160 7552 0 - Live 0xffffffffa06e9000
nfsd 208660 2 - Live 0xffffffffa06a8000
auth_rpcgss 39179 1 nfsd, Live 0xffffffffa0698000
oid_registry 2490 1 auth_rpcgss, Live 0xffffffffa0694000
nfs_acl 2285 1 nfsd, Live 0xffffffffa0690000
sha512_generic 5023 0 - Live 0xffffffffa068b000
nfs 127233 0 - Live 0xffffffffa065b000
lockd 57962 2 nfsd,nfs, Live 0xffffffffa0645000
fscache 34198 1 nfs, Live 0xffffffffa0636000
sha1_ssse3 9266 0 - Live 0xffffffffa0630000
sha1_generic 2064 1 sha1_ssse3, Live 0xffffffffa062c000
sunrpc 185043 6 nfsd,auth_rpcgss,nfs_acl,nfs,lockd, Live 0xffffffffa05ea000
md5 1803 0 - Live 0xffffffffa05e6000
crypto_null 2624 0 - Live 0xffffffffa05e2000
af_key 25880 0 - Live 0xffffffffa05d6000
xfrm_algo 6101 1 af_key, Live 0xffffffffa05d1000
ves1820 5159 1 - Live 0xffffffffa05cc000
btusb 14810 0 - Live 0xffffffffa05bc000
bluetooth 183572 24 rfcomm,bnep,btusb, Live 0xffffffffa054a000
stv0297 6493 1 - Live 0xffffffffa052f000
snd_rawmidi 17913 1 snd_usbmidi_lib, Live 0xffffffffa0525000
snd_pcm_oss 32083 0 - Live 0xffffffffa0518000
snd_mixer_oss 12485 1 snd_pcm_oss, Live 0xffffffffa0510000
snd_pcm 73594 4 snd_usb_audio,snd_hda_intel,snd_hda_codec,snd_pcm_oss, Live 0xffffffffa04f5000
snd_page_alloc 7172 2 snd_hda_intel,snd_pcm, Live 0xffffffffa04f0000
dvb_ttpci 93699 0 - Live 0xffffffffa04d1000
saa7146_vv 26567 1 dvb_ttpci, Live 0xffffffffa04c5000
videobuf_dma_sg 8015 1 saa7146_vv, Live 0xffffffffa04bf000
videobuf_core 15578 2 saa7146_vv,videobuf_dma_sg, Live 0xffffffffa04b7000
v4l2_common 7907 1 saa7146_vv, Live 0xffffffffa04b1000
budget_ci 21012 0 - Live 0xffffffffa04a7000
videodev 97317 2 saa7146_vv,v4l2_common, Live 0xffffffffa0486000
budget_core 7679 1 budget_ci, Live 0xffffffffa0481000
ttpci_eeprom 1985 2 dvb_ttpci,budget_core, Live 0xffffffffa0479000
saa7146 11356 4 dvb_ttpci,saa7146_vv,budget_ci,budget_core, Live 0xffffffffa046b000
rc_core 13478 2 budget_ci, Live 0xffffffffa044a000
dvb_core 68839 3 dvb_ttpci,budget_ci,budget_core, Live 0xffffffffa0431000
snd_seq_oss 33717 1 - Loading 0xffffffffa041b000
snd_seq_midi_event 5740 1 snd_seq_oss, Live 0xffffffffa0416000
snd_seq 44232 2 snd_seq_oss,snd_seq_midi_event, Live 0xffffffffa0404000
snd_seq_device 5560 3 snd_rawmidi,snd_seq_oss,snd_seq, Live 0xffffffffa03ff000
snd_timer 17417 2 snd_pcm,snd_seq, Live 0xffffffffa03f6000
snd 58793 14 snd_usb_audio,snd_usbmidi_lib,snd_hda_codec_realtek,snd_hda_intel,snd_hda_codec,snd_hwdep,snd_rawmidi,snd_pcm_oss,snd_mixer_oss,snd_pcm,snd_seq_oss,snd_seq,snd_seq_device,snd_timer, Live 0xffffffffa03df000
pcspkr 1926 0 - Live 0xffffffffa03db000
psmouse 52563 0 - Live 0xffffffffa03c6000
serio_raw 4517 0 - Live 0xffffffffa03c1000
soundcore 5811 1 snd, Live 0xffffffffa03b7000
evdev 8465 0 - Live 0xffffffffa039d000
kvm_intel 122108 0 - Live 0xffffffffa0351000
kvm 342589 1 kvm_intel, Live 0xffffffffa0271000
usb_storage 46166 0 - Live 0xffffffffa025c000
fuse 65800 1 - Live 0xffffffffa0243000
ecryptfs 80646 0 - Live 0xffffffffa0227000
cbc 2574 0 - Live 0xffffffffa0223000
sha256_ssse3 16172 2 - Live 0xffffffffa021c000
sha256_generic 9882 1 sha256_ssse3, Live 0xffffffffa0216000
hmac 2673 1 - Live 0xffffffffa0212000
encrypted_keys 9378 1 ecryptfs, Live 0xffffffffa020b000
autofs4 20984 2 - Live 0xffffffffa0200000
ext4 434295 5 - Live 0xffffffffa0173000
crc16 1541 2 bluetooth,ext4, Live 0xffffffffa016f000
jbd2 83146 1 ext4, Live 0xffffffffa0150000
btrfs 682625 1 - Live 0xffffffffa008b000
crc32c 1610 1 - Live 0xffffffffa0087000
libcrc32c 1147 1 btrfs, Live 0xffffffffa0083000
xor 11190 1 btrfs, Live 0xffffffffa007d000
zlib_deflate 18739 2 deflate,btrfs, Live 0xffffffffa0075000
raid6_pq 92000 1 btrfs, Live 0xffffffffa005a000
nbd 8786 0 - Live 0xffffffffa0053000
firewire_ohci 27516 0 - Live 0xffffffffa0048000
firewire_core 49041 1 firewire_ohci, Live 0xffffffffa0035000
crc_itu_t 1565 1 firewire_core, Live 0xffffffffa0031000
forcedeth 50647 0 - Live 0xffffffffa001e000
floppy 53437 0 - Live 0xffffffffa0009000
ohci_hcd 18001 0 - Live 0xffffffffa0000000

BYtE
Philipp
--
/ / (_)__ __ ____ __ Philipp Hahn
/ /__/ / _ \/ // /\ \/ /
/____/_/_//_/\_,_/ /_/\_\ [email protected]


2013-07-16 05:44:52

by Rusty Russell

[permalink] [raw]
Subject: Re: [BUG] 3.10.[01] modprobe snd-... hangs

Philipp Matthias Hahn <[email protected]> writes:
> Hello,
>
> My x86_64 systems has some trouble loading some ALSA snd-* modules since
> the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
> loading snd-intel-hda and snd-audio-usb by hand still works.

Not a known problem to me, at least. Perhaps it's a dep loop somehow.

> ...
> 1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
> 1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq

This was first, and it's waiting. Which means it must be doing
something weird, because snd_seq_oss is loading now:

> snd_seq_oss 33717 1 - Loading 0xffffffffa041b000

Perhaps in the tangle of modprobe install commands somewhere this gets
invoked?

> # ps axf
> 460 ? S 0:00 \_ [kworker/u8:3]
> 1087 ? S 0:00 | \_ [kworker/u8:3]
> 1092 ? S 0:00 | \_ /sbin/modprobe -q -- snd-seq-client-14

On my systems, that's snd-seq-dummy, which depends on snd_seq. Which,
in fact, is already loaded.

Lucas, any clues?

Full quote below.

Cheers,
Rusty.

Philipp Matthias Hahn <[email protected]> writes:
> Hello,
>
> My x86_64 systems has some trouble loading some ALSA snd-* modules since
> the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
> loading snd-intel-hda and snd-audio-usb by hand still works.
>
> # ps axf
> 460 ? S 0:00 \_ [kworker/u8:3]
> 1087 ? S 0:00 | \_ [kworker/u8:3]
> 1092 ? S 0:00 | \_ /sbin/modprobe -q -- snd-seq-client-14
> ...
> 1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
> 1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq
> 1115 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd-rawmidi && { /sbin/modprobe --q
> 1154 ? S 0:00 \_ /sbin/modprobe --quiet snd-seq-midi
> 1119 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd-rawmidi && { /sbin/modprobe --q
> 1148 ? S 0:00 \_ /sbin/modprobe --quiet snd-seq-midi
>
> In /var/log/daemon.log I find the following messages:
> Jul 15 19:58:44 scout udevd[912]: timeout: killing '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc01ip00in00' [1044]
> Jul 15 19:58:56 scout udevd[912]: '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc01ip00in00' [1044] terminated by signal 9 (Killed)
> Jul 15 19:58:56 scout udevd[919]: timeout: killing '/sbin/modprobe -b pci:v000010DEd0000026Csv00001462sd00007350bc04sc03i00' [1051]
> Jul 15 19:58:56 scout udevd[914]: timeout: killing '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc03ip00in01' [1045]
> Jul 15 19:58:56 scout udevd[919]: '/sbin/modprobe -b pci:v000010DEd0000026Csv00001462sd00007350bc04sc03i00' [1051] terminated by signal 9 (Killed)
> Jul 15 19:58:56 scout udevd[914]: '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc03ip00in01' [1045] terminated by signal 9 (Killed)
>
>
> This is a Debian sid system
> # modprobe -V
> kmod version 9
>
> # echo t >/proc/sysrq-trigger
> produces too much output to include the modprobe processes. I already
> stopped most processes, but that is not enough.
>
>
> # cat /proc/1092/syscall
> 175 0x7effcad92000 0xafe8 0x7effca9c2f88 0x7effca6ea3aa 0x0 0x0 0x7fff3e3de648 0x7effca6eef8a
>
> # cat /proc/1080/syscall
> 175 0x7fe01b25e000 0xafe8 0x7fe01ae8ef88 0x7fe01abb63aa 0x3 0x0 0x7fffba8cc748 0x7fe01abbaf8a
>
> # cat /proc/1154/syscall
> 175 0x7fc157a7b000 0xafe8 0x7fc1576abf88 0x7fc1573d33aa 0x3 0x0 0x7fff05809e58 0x7fc1573d7f8a
>
> # cat /proc/1148/syscall
> 175 0x7fc7159d5000 0xafe8 0x7fc715605f88 0x7fc71532d3aa 0x3 0x0 0x7fff47a1f3c8 0x7fc715331f8a
>
> Is this a know bug or has someone seen similar problems?
>
> # cat /proc/modules
> ip6table_filter 1575 0 - Live 0xffffffffa0893000
> ip6_tables 13784 1 ip6table_filter, Live 0xffffffffa088b000
> ebtable_nat 1887 0 - Live 0xffffffffa0887000
> ebtables 19917 1 ebtable_nat, Live 0xffffffffa087e000
> snd_usb_audio 124196 0 - Live 0xffffffffa0851000
> snd_usbmidi_lib 16982 1 snd_usb_audio, Live 0xffffffffa0848000
> rfcomm 28731 10 - Live 0xffffffffa083a000
> bnep 9786 2 - Live 0xffffffffa0833000
> snd_hda_codec_realtek 37669 1 - Live 0xffffffffa0823000
> snd_hda_intel 31432 0 - Live 0xffffffffa0814000
> snd_hda_codec 140669 2 snd_hda_codec_realtek,snd_hda_intel, Live 0xffffffffa07e2000
> snd_hwdep 5627 2 snd_usb_audio,snd_hda_codec, Live 0xffffffffa07dd000
> iptable_filter 1618 1 - Live 0xffffffffa07d9000
> xt_owner 1326 1 - Live 0xffffffffa07d5000
> ip_tables 13390 1 iptable_filter, Live 0xffffffffa07cd000
> x_tables 18433 6 ip6table_filter,ip6_tables,ebtables,iptable_filter,xt_owner,ip_tables, Live 0xffffffffa07c3000
> cpufreq_conservative 7015 0 - Live 0xffffffffa07bd000
> cpufreq_ondemand 8945 0 - Live 0xffffffffa07b6000
> cpufreq_powersave 1010 0 - Live 0xffffffffa07b2000
> cpufreq_userspace 2136 0 - Live 0xffffffffa07ae000
> binfmt_misc 6479 1 - Live 0xffffffffa07a9000
> bridge 74378 0 - Live 0xffffffffa078d000
> stp 1908 1 bridge, Live 0xffffffffa0789000
> llc 4485 2 bridge,stp, Live 0xffffffffa0784000
> deflate 1873 0 - Live 0xffffffffa0780000
> ctr 3633 0 - Live 0xffffffffa077c000
> twofish_generic 5715 0 - Live 0xffffffffa0777000
> twofish_x86_64_3way 19885 0 - Live 0xffffffffa076f000
> twofish_x86_64 5503 1 twofish_x86_64_3way, Live 0xffffffffa076a000
> twofish_common 13133 3 twofish_generic,twofish_x86_64_3way,twofish_x86_64, Live 0xffffffffa0763000
> camellia_generic 18308 0 - Live 0xffffffffa075b000
> camellia_x86_64 45885 0 - Live 0xffffffffa074b000
> serpent_sse2_x86_64 44963 0 - Live 0xffffffffa073d000
> serpent_generic 21243 1 serpent_sse2_x86_64, Live 0xffffffffa0734000
> ablk_helper 2284 1 serpent_sse2_x86_64, Live 0xffffffffa0730000
> cryptd 7992 1 ablk_helper, Live 0xffffffffa072a000
> xts 2958 3 twofish_x86_64_3way,camellia_x86_64,serpent_sse2_x86_64, Live 0xffffffffa0726000
> lrw 3584 3 twofish_x86_64_3way,camellia_x86_64,serpent_sse2_x86_64, Live 0xffffffffa0722000
> gf128mul 6580 2 xts,lrw, Live 0xffffffffa071d000
> glue_helper 4810 3 twofish_x86_64_3way,camellia_x86_64,serpent_sse2_x86_64, Live 0xffffffffa0718000
> blowfish_generic 3194 0 - Live 0xffffffffa0714000
> blowfish_x86_64 14084 0 - Live 0xffffffffa070d000
> blowfish_common 6425 2 blowfish_generic,blowfish_x86_64, Live 0xffffffffa0708000
> cast5_generic 10378 0 - Live 0xffffffffa0702000
> cast_common 5351 1 cast5_generic, Live 0xffffffffa06fd000
> des_generic 16147 0 - Live 0xffffffffa06f6000
> cmac 2460 0 - Live 0xffffffffa06f2000
> xcbc 2423 0 - Live 0xffffffffa06ee000
> rmd160 7552 0 - Live 0xffffffffa06e9000
> nfsd 208660 2 - Live 0xffffffffa06a8000
> auth_rpcgss 39179 1 nfsd, Live 0xffffffffa0698000
> oid_registry 2490 1 auth_rpcgss, Live 0xffffffffa0694000
> nfs_acl 2285 1 nfsd, Live 0xffffffffa0690000
> sha512_generic 5023 0 - Live 0xffffffffa068b000
> nfs 127233 0 - Live 0xffffffffa065b000
> lockd 57962 2 nfsd,nfs, Live 0xffffffffa0645000
> fscache 34198 1 nfs, Live 0xffffffffa0636000
> sha1_ssse3 9266 0 - Live 0xffffffffa0630000
> sha1_generic 2064 1 sha1_ssse3, Live 0xffffffffa062c000
> sunrpc 185043 6 nfsd,auth_rpcgss,nfs_acl,nfs,lockd, Live 0xffffffffa05ea000
> md5 1803 0 - Live 0xffffffffa05e6000
> crypto_null 2624 0 - Live 0xffffffffa05e2000
> af_key 25880 0 - Live 0xffffffffa05d6000
> xfrm_algo 6101 1 af_key, Live 0xffffffffa05d1000
> ves1820 5159 1 - Live 0xffffffffa05cc000
> btusb 14810 0 - Live 0xffffffffa05bc000
> bluetooth 183572 24 rfcomm,bnep,btusb, Live 0xffffffffa054a000
> stv0297 6493 1 - Live 0xffffffffa052f000
> snd_rawmidi 17913 1 snd_usbmidi_lib, Live 0xffffffffa0525000
> snd_pcm_oss 32083 0 - Live 0xffffffffa0518000
> snd_mixer_oss 12485 1 snd_pcm_oss, Live 0xffffffffa0510000
> snd_pcm 73594 4 snd_usb_audio,snd_hda_intel,snd_hda_codec,snd_pcm_oss, Live 0xffffffffa04f5000
> snd_page_alloc 7172 2 snd_hda_intel,snd_pcm, Live 0xffffffffa04f0000
> dvb_ttpci 93699 0 - Live 0xffffffffa04d1000
> saa7146_vv 26567 1 dvb_ttpci, Live 0xffffffffa04c5000
> videobuf_dma_sg 8015 1 saa7146_vv, Live 0xffffffffa04bf000
> videobuf_core 15578 2 saa7146_vv,videobuf_dma_sg, Live 0xffffffffa04b7000
> v4l2_common 7907 1 saa7146_vv, Live 0xffffffffa04b1000
> budget_ci 21012 0 - Live 0xffffffffa04a7000
> videodev 97317 2 saa7146_vv,v4l2_common, Live 0xffffffffa0486000
> budget_core 7679 1 budget_ci, Live 0xffffffffa0481000
> ttpci_eeprom 1985 2 dvb_ttpci,budget_core, Live 0xffffffffa0479000
> saa7146 11356 4 dvb_ttpci,saa7146_vv,budget_ci,budget_core, Live 0xffffffffa046b000
> rc_core 13478 2 budget_ci, Live 0xffffffffa044a000
> dvb_core 68839 3 dvb_ttpci,budget_ci,budget_core, Live 0xffffffffa0431000
> snd_seq_oss 33717 1 - Loading 0xffffffffa041b000
> snd_seq_midi_event 5740 1 snd_seq_oss, Live 0xffffffffa0416000
> snd_seq 44232 2 snd_seq_oss,snd_seq_midi_event, Live 0xffffffffa0404000
> snd_seq_device 5560 3 snd_rawmidi,snd_seq_oss,snd_seq, Live 0xffffffffa03ff000
> snd_timer 17417 2 snd_pcm,snd_seq, Live 0xffffffffa03f6000
> snd 58793 14 snd_usb_audio,snd_usbmidi_lib,snd_hda_codec_realtek,snd_hda_intel,snd_hda_codec,snd_hwdep,snd_rawmidi,snd_pcm_oss,snd_mixer_oss,snd_pcm,snd_seq_oss,snd_seq,snd_seq_device,snd_timer, Live 0xffffffffa03df000
> pcspkr 1926 0 - Live 0xffffffffa03db000
> psmouse 52563 0 - Live 0xffffffffa03c6000
> serio_raw 4517 0 - Live 0xffffffffa03c1000
> soundcore 5811 1 snd, Live 0xffffffffa03b7000
> evdev 8465 0 - Live 0xffffffffa039d000
> kvm_intel 122108 0 - Live 0xffffffffa0351000
> kvm 342589 1 kvm_intel, Live 0xffffffffa0271000
> usb_storage 46166 0 - Live 0xffffffffa025c000
> fuse 65800 1 - Live 0xffffffffa0243000
> ecryptfs 80646 0 - Live 0xffffffffa0227000
> cbc 2574 0 - Live 0xffffffffa0223000
> sha256_ssse3 16172 2 - Live 0xffffffffa021c000
> sha256_generic 9882 1 sha256_ssse3, Live 0xffffffffa0216000
> hmac 2673 1 - Live 0xffffffffa0212000
> encrypted_keys 9378 1 ecryptfs, Live 0xffffffffa020b000
> autofs4 20984 2 - Live 0xffffffffa0200000
> ext4 434295 5 - Live 0xffffffffa0173000
> crc16 1541 2 bluetooth,ext4, Live 0xffffffffa016f000
> jbd2 83146 1 ext4, Live 0xffffffffa0150000
> btrfs 682625 1 - Live 0xffffffffa008b000
> crc32c 1610 1 - Live 0xffffffffa0087000
> libcrc32c 1147 1 btrfs, Live 0xffffffffa0083000
> xor 11190 1 btrfs, Live 0xffffffffa007d000
> zlib_deflate 18739 2 deflate,btrfs, Live 0xffffffffa0075000
> raid6_pq 92000 1 btrfs, Live 0xffffffffa005a000
> nbd 8786 0 - Live 0xffffffffa0053000
> firewire_ohci 27516 0 - Live 0xffffffffa0048000
> firewire_core 49041 1 firewire_ohci, Live 0xffffffffa0035000
> crc_itu_t 1565 1 firewire_core, Live 0xffffffffa0031000
> forcedeth 50647 0 - Live 0xffffffffa001e000
> floppy 53437 0 - Live 0xffffffffa0009000
> ohci_hcd 18001 0 - Live 0xffffffffa0000000
>
> BYtE
> Philipp
> --
> / / (_)__ __ ____ __ Philipp Hahn
> / /__/ / _ \/ // /\ \/ /
> /____/_/_//_/\_,_/ /_/\_\ [email protected]

2013-07-16 06:42:23

by Takashi Iwai

[permalink] [raw]
Subject: Re: [alsa-devel] [BUG] 3.10.[01] modprobe snd-... hangs

At Tue, 16 Jul 2013 15:11:51 +0930,
Rusty Russell wrote:
>
> Philipp Matthias Hahn <[email protected]> writes:
> > Hello,
> >
> > My x86_64 systems has some trouble loading some ALSA snd-* modules since
> > the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
> > loading snd-intel-hda and snd-audio-usb by hand still works.
>
> Not a known problem to me, at least. Perhaps it's a dep loop somehow.

I remember that someone reported it being Debian specific snd-seq-oss
loading stuff.

> > ...
> > 1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
> > 1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq
>
> This was first, and it's waiting. Which means it must be doing
> something weird, because snd_seq_oss is loading now:
>
> > snd_seq_oss 33717 1 - Loading 0xffffffffa041b000
>
> Perhaps in the tangle of modprobe install commands somewhere this gets
> invoked?

Likely, but I wonder what triggered a bug suddenly on 3.10.
There is absolutely no change in sound/core/seq/*, and through a quick
look, I couldn't find any suspicious change in kernel/module.c that
may lead to this problem between 3.9 and 3.10.

Philipp, can you get a sysrq-T trace while the stall?


thanks,

Takashi

> > # ps axf
> > 460 ? S 0:00 \_ [kworker/u8:3]
> > 1087 ? S 0:00 | \_ [kworker/u8:3]
> > 1092 ? S 0:00 | \_ /sbin/modprobe -q -- snd-seq-client-14
>
> On my systems, that's snd-seq-dummy, which depends on snd_seq. Which,
> in fact, is already loaded.
>
> Lucas, any clues?
>
> Full quote below.
>
> Cheers,
> Rusty.
>
> Philipp Matthias Hahn <[email protected]> writes:
> > Hello,
> >
> > My x86_64 systems has some trouble loading some ALSA snd-* modules since
> > the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
> > loading snd-intel-hda and snd-audio-usb by hand still works.
> >
> > # ps axf
> > 460 ? S 0:00 \_ [kworker/u8:3]
> > 1087 ? S 0:00 | \_ [kworker/u8:3]
> > 1092 ? S 0:00 | \_ /sbin/modprobe -q -- snd-seq-client-14
> > ...
> > 1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
> > 1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq
> > 1115 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd-rawmidi && { /sbin/modprobe --q
> > 1154 ? S 0:00 \_ /sbin/modprobe --quiet snd-seq-midi
> > 1119 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd-rawmidi && { /sbin/modprobe --q
> > 1148 ? S 0:00 \_ /sbin/modprobe --quiet snd-seq-midi
> >
> > In /var/log/daemon.log I find the following messages:
> > Jul 15 19:58:44 scout udevd[912]: timeout: killing '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc01ip00in00' [1044]
> > Jul 15 19:58:56 scout udevd[912]: '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc01ip00in00' [1044] terminated by signal 9 (Killed)
> > Jul 15 19:58:56 scout udevd[919]: timeout: killing '/sbin/modprobe -b pci:v000010DEd0000026Csv00001462sd00007350bc04sc03i00' [1051]
> > Jul 15 19:58:56 scout udevd[914]: timeout: killing '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc03ip00in01' [1045]
> > Jul 15 19:58:56 scout udevd[919]: '/sbin/modprobe -b pci:v000010DEd0000026Csv00001462sd00007350bc04sc03i00' [1051] terminated by signal 9 (Killed)
> > Jul 15 19:58:56 scout udevd[914]: '/sbin/modprobe -b usb:vFC08p0101d0250dc00dsc00dp00ic01isc03ip00in01' [1045] terminated by signal 9 (Killed)
> >
> >
> > This is a Debian sid system
> > # modprobe -V
> > kmod version 9
> >
> > # echo t >/proc/sysrq-trigger
> > produces too much output to include the modprobe processes. I already
> > stopped most processes, but that is not enough.
> >
> >
> > # cat /proc/1092/syscall
> > 175 0x7effcad92000 0xafe8 0x7effca9c2f88 0x7effca6ea3aa 0x0 0x0 0x7fff3e3de648 0x7effca6eef8a
> >
> > # cat /proc/1080/syscall
> > 175 0x7fe01b25e000 0xafe8 0x7fe01ae8ef88 0x7fe01abb63aa 0x3 0x0 0x7fffba8cc748 0x7fe01abbaf8a
> >
> > # cat /proc/1154/syscall
> > 175 0x7fc157a7b000 0xafe8 0x7fc1576abf88 0x7fc1573d33aa 0x3 0x0 0x7fff05809e58 0x7fc1573d7f8a
> >
> > # cat /proc/1148/syscall
> > 175 0x7fc7159d5000 0xafe8 0x7fc715605f88 0x7fc71532d3aa 0x3 0x0 0x7fff47a1f3c8 0x7fc715331f8a
> >
> > Is this a know bug or has someone seen similar problems?
> >
> > # cat /proc/modules
> > ip6table_filter 1575 0 - Live 0xffffffffa0893000
> > ip6_tables 13784 1 ip6table_filter, Live 0xffffffffa088b000
> > ebtable_nat 1887 0 - Live 0xffffffffa0887000
> > ebtables 19917 1 ebtable_nat, Live 0xffffffffa087e000
> > snd_usb_audio 124196 0 - Live 0xffffffffa0851000
> > snd_usbmidi_lib 16982 1 snd_usb_audio, Live 0xffffffffa0848000
> > rfcomm 28731 10 - Live 0xffffffffa083a000
> > bnep 9786 2 - Live 0xffffffffa0833000
> > snd_hda_codec_realtek 37669 1 - Live 0xffffffffa0823000
> > snd_hda_intel 31432 0 - Live 0xffffffffa0814000
> > snd_hda_codec 140669 2 snd_hda_codec_realtek,snd_hda_intel, Live 0xffffffffa07e2000
> > snd_hwdep 5627 2 snd_usb_audio,snd_hda_codec, Live 0xffffffffa07dd000
> > iptable_filter 1618 1 - Live 0xffffffffa07d9000
> > xt_owner 1326 1 - Live 0xffffffffa07d5000
> > ip_tables 13390 1 iptable_filter, Live 0xffffffffa07cd000
> > x_tables 18433 6 ip6table_filter,ip6_tables,ebtables,iptable_filter,xt_owner,ip_tables, Live 0xffffffffa07c3000
> > cpufreq_conservative 7015 0 - Live 0xffffffffa07bd000
> > cpufreq_ondemand 8945 0 - Live 0xffffffffa07b6000
> > cpufreq_powersave 1010 0 - Live 0xffffffffa07b2000
> > cpufreq_userspace 2136 0 - Live 0xffffffffa07ae000
> > binfmt_misc 6479 1 - Live 0xffffffffa07a9000
> > bridge 74378 0 - Live 0xffffffffa078d000
> > stp 1908 1 bridge, Live 0xffffffffa0789000
> > llc 4485 2 bridge,stp, Live 0xffffffffa0784000
> > deflate 1873 0 - Live 0xffffffffa0780000
> > ctr 3633 0 - Live 0xffffffffa077c000
> > twofish_generic 5715 0 - Live 0xffffffffa0777000
> > twofish_x86_64_3way 19885 0 - Live 0xffffffffa076f000
> > twofish_x86_64 5503 1 twofish_x86_64_3way, Live 0xffffffffa076a000
> > twofish_common 13133 3 twofish_generic,twofish_x86_64_3way,twofish_x86_64, Live 0xffffffffa0763000
> > camellia_generic 18308 0 - Live 0xffffffffa075b000
> > camellia_x86_64 45885 0 - Live 0xffffffffa074b000
> > serpent_sse2_x86_64 44963 0 - Live 0xffffffffa073d000
> > serpent_generic 21243 1 serpent_sse2_x86_64, Live 0xffffffffa0734000
> > ablk_helper 2284 1 serpent_sse2_x86_64, Live 0xffffffffa0730000
> > cryptd 7992 1 ablk_helper, Live 0xffffffffa072a000
> > xts 2958 3 twofish_x86_64_3way,camellia_x86_64,serpent_sse2_x86_64, Live 0xffffffffa0726000
> > lrw 3584 3 twofish_x86_64_3way,camellia_x86_64,serpent_sse2_x86_64, Live 0xffffffffa0722000
> > gf128mul 6580 2 xts,lrw, Live 0xffffffffa071d000
> > glue_helper 4810 3 twofish_x86_64_3way,camellia_x86_64,serpent_sse2_x86_64, Live 0xffffffffa0718000
> > blowfish_generic 3194 0 - Live 0xffffffffa0714000
> > blowfish_x86_64 14084 0 - Live 0xffffffffa070d000
> > blowfish_common 6425 2 blowfish_generic,blowfish_x86_64, Live 0xffffffffa0708000
> > cast5_generic 10378 0 - Live 0xffffffffa0702000
> > cast_common 5351 1 cast5_generic, Live 0xffffffffa06fd000
> > des_generic 16147 0 - Live 0xffffffffa06f6000
> > cmac 2460 0 - Live 0xffffffffa06f2000
> > xcbc 2423 0 - Live 0xffffffffa06ee000
> > rmd160 7552 0 - Live 0xffffffffa06e9000
> > nfsd 208660 2 - Live 0xffffffffa06a8000
> > auth_rpcgss 39179 1 nfsd, Live 0xffffffffa0698000
> > oid_registry 2490 1 auth_rpcgss, Live 0xffffffffa0694000
> > nfs_acl 2285 1 nfsd, Live 0xffffffffa0690000
> > sha512_generic 5023 0 - Live 0xffffffffa068b000
> > nfs 127233 0 - Live 0xffffffffa065b000
> > lockd 57962 2 nfsd,nfs, Live 0xffffffffa0645000
> > fscache 34198 1 nfs, Live 0xffffffffa0636000
> > sha1_ssse3 9266 0 - Live 0xffffffffa0630000
> > sha1_generic 2064 1 sha1_ssse3, Live 0xffffffffa062c000
> > sunrpc 185043 6 nfsd,auth_rpcgss,nfs_acl,nfs,lockd, Live 0xffffffffa05ea000
> > md5 1803 0 - Live 0xffffffffa05e6000
> > crypto_null 2624 0 - Live 0xffffffffa05e2000
> > af_key 25880 0 - Live 0xffffffffa05d6000
> > xfrm_algo 6101 1 af_key, Live 0xffffffffa05d1000
> > ves1820 5159 1 - Live 0xffffffffa05cc000
> > btusb 14810 0 - Live 0xffffffffa05bc000
> > bluetooth 183572 24 rfcomm,bnep,btusb, Live 0xffffffffa054a000
> > stv0297 6493 1 - Live 0xffffffffa052f000
> > snd_rawmidi 17913 1 snd_usbmidi_lib, Live 0xffffffffa0525000
> > snd_pcm_oss 32083 0 - Live 0xffffffffa0518000
> > snd_mixer_oss 12485 1 snd_pcm_oss, Live 0xffffffffa0510000
> > snd_pcm 73594 4 snd_usb_audio,snd_hda_intel,snd_hda_codec,snd_pcm_oss, Live 0xffffffffa04f5000
> > snd_page_alloc 7172 2 snd_hda_intel,snd_pcm, Live 0xffffffffa04f0000
> > dvb_ttpci 93699 0 - Live 0xffffffffa04d1000
> > saa7146_vv 26567 1 dvb_ttpci, Live 0xffffffffa04c5000
> > videobuf_dma_sg 8015 1 saa7146_vv, Live 0xffffffffa04bf000
> > videobuf_core 15578 2 saa7146_vv,videobuf_dma_sg, Live 0xffffffffa04b7000
> > v4l2_common 7907 1 saa7146_vv, Live 0xffffffffa04b1000
> > budget_ci 21012 0 - Live 0xffffffffa04a7000
> > videodev 97317 2 saa7146_vv,v4l2_common, Live 0xffffffffa0486000
> > budget_core 7679 1 budget_ci, Live 0xffffffffa0481000
> > ttpci_eeprom 1985 2 dvb_ttpci,budget_core, Live 0xffffffffa0479000
> > saa7146 11356 4 dvb_ttpci,saa7146_vv,budget_ci,budget_core, Live 0xffffffffa046b000
> > rc_core 13478 2 budget_ci, Live 0xffffffffa044a000
> > dvb_core 68839 3 dvb_ttpci,budget_ci,budget_core, Live 0xffffffffa0431000
> > snd_seq_oss 33717 1 - Loading 0xffffffffa041b000
> > snd_seq_midi_event 5740 1 snd_seq_oss, Live 0xffffffffa0416000
> > snd_seq 44232 2 snd_seq_oss,snd_seq_midi_event, Live 0xffffffffa0404000
> > snd_seq_device 5560 3 snd_rawmidi,snd_seq_oss,snd_seq, Live 0xffffffffa03ff000
> > snd_timer 17417 2 snd_pcm,snd_seq, Live 0xffffffffa03f6000
> > snd 58793 14 snd_usb_audio,snd_usbmidi_lib,snd_hda_codec_realtek,snd_hda_intel,snd_hda_codec,snd_hwdep,snd_rawmidi,snd_pcm_oss,snd_mixer_oss,snd_pcm,snd_seq_oss,snd_seq,snd_seq_device,snd_timer, Live 0xffffffffa03df000
> > pcspkr 1926 0 - Live 0xffffffffa03db000
> > psmouse 52563 0 - Live 0xffffffffa03c6000
> > serio_raw 4517 0 - Live 0xffffffffa03c1000
> > soundcore 5811 1 snd, Live 0xffffffffa03b7000
> > evdev 8465 0 - Live 0xffffffffa039d000
> > kvm_intel 122108 0 - Live 0xffffffffa0351000
> > kvm 342589 1 kvm_intel, Live 0xffffffffa0271000
> > usb_storage 46166 0 - Live 0xffffffffa025c000
> > fuse 65800 1 - Live 0xffffffffa0243000
> > ecryptfs 80646 0 - Live 0xffffffffa0227000
> > cbc 2574 0 - Live 0xffffffffa0223000
> > sha256_ssse3 16172 2 - Live 0xffffffffa021c000
> > sha256_generic 9882 1 sha256_ssse3, Live 0xffffffffa0216000
> > hmac 2673 1 - Live 0xffffffffa0212000
> > encrypted_keys 9378 1 ecryptfs, Live 0xffffffffa020b000
> > autofs4 20984 2 - Live 0xffffffffa0200000
> > ext4 434295 5 - Live 0xffffffffa0173000
> > crc16 1541 2 bluetooth,ext4, Live 0xffffffffa016f000
> > jbd2 83146 1 ext4, Live 0xffffffffa0150000
> > btrfs 682625 1 - Live 0xffffffffa008b000
> > crc32c 1610 1 - Live 0xffffffffa0087000
> > libcrc32c 1147 1 btrfs, Live 0xffffffffa0083000
> > xor 11190 1 btrfs, Live 0xffffffffa007d000
> > zlib_deflate 18739 2 deflate,btrfs, Live 0xffffffffa0075000
> > raid6_pq 92000 1 btrfs, Live 0xffffffffa005a000
> > nbd 8786 0 - Live 0xffffffffa0053000
> > firewire_ohci 27516 0 - Live 0xffffffffa0048000
> > firewire_core 49041 1 firewire_ohci, Live 0xffffffffa0035000
> > crc_itu_t 1565 1 firewire_core, Live 0xffffffffa0031000
> > forcedeth 50647 0 - Live 0xffffffffa001e000
> > floppy 53437 0 - Live 0xffffffffa0009000
> > ohci_hcd 18001 0 - Live 0xffffffffa0000000
> >
> > BYtE
> > Philipp
> > --
> > / / (_)__ __ ____ __ Philipp Hahn
> > / /__/ / _ \/ // /\ \/ /
> > /____/_/_//_/\_,_/ /_/\_\ [email protected]
> _______________________________________________
> Alsa-devel mailing list
> [email protected]
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
>

2013-07-16 06:42:58

by Lucas De Marchi

[permalink] [raw]
Subject: Re: [BUG] 3.10.[01] modprobe snd-... hangs

On Tue, Jul 16, 2013 at 2:41 AM, Rusty Russell <[email protected]> wrote:
> Philipp Matthias Hahn <[email protected]> writes:
>> Hello,
>>
>> My x86_64 systems has some trouble loading some ALSA snd-* modules since
>> the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
>> loading snd-intel-hda and snd-audio-usb by hand still works.
>
> Not a known problem to me, at least. Perhaps it's a dep loop somehow.

First thing to check is the /etc/modprobe.d/*.conf file that contains
these install commands. Did they change besides the kernel upgrade?

[
Not really related to this, but... people/distros should stop using
install commands for things like this. By using softdeps kmod is smart
enough to detect and (possibly) break loops. With install commands it
can't because it has no idea what the install command will do.
]

>
>> ...
>> 1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
>> 1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq
>
> This was first, and it's waiting. Which means it must be doing
> something weird, because snd_seq_oss is loading now:
>
>> snd_seq_oss 33717 1 - Loading 0xffffffffa041b000

Searching kmod's log, I guess Debian still has:

install snd_seq modprobe --ignore-install snd-seq $CMDLINE_OPTS && {
modprobe --quiet snd-seq-midi ; modprobe --quiet snd-seq-oss ; : ; }

>
> Perhaps in the tangle of modprobe install commands somewhere this gets
> invoked?
>
>> # ps axf
>> 460 ? S 0:00 \_ [kworker/u8:3]
>> 1087 ? S 0:00 | \_ [kworker/u8:3]
>> 1092 ? S 0:00 | \_ /sbin/modprobe -q -- snd-seq-client-14

Weird... this is coming from a request_module(). Greping... this
should only be coming from

git grep request_module | grep snd-seq-client
sound/core/seq/seq_clientmgr.c: request_module("snd-seq-client-%i",

Philipp, which kernel are you upgrading from? I don't see anything to
blame in the changes for the past releases. Any chance a bad entry in
your .conf was added too? You may want to paste the output of modprobe
-c, at least until "# End of configuration files. Dumping indexes
now:"

>
> On my systems, that's snd-seq-dummy, which depends on snd_seq. Which,
> in fact, is already loaded.
>
> Lucas, any clues?

I don't think I could help, but we need more data, like the ones above.


Lucas De Marchi

2013-07-16 07:49:50

by Damien Wyart

[permalink] [raw]
Subject: Re: [alsa-devel] [BUG] 3.10.[01] modprobe snd-... hangs

* Takashi Iwai <[email protected]> [2013-07-16 08:43]:
> At Tue, 16 Jul 2013 15:11:51 +0930,
> Rusty Russell wrote:

> > Philipp Matthias Hahn <[email protected]> writes:
> > > Hello,

> > > My x86_64 systems has some trouble loading some ALSA snd-* modules since
> > > the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
> > > loading snd-intel-hda and snd-audio-usb by hand still works.

> > Not a known problem to me, at least. Perhaps it's a dep loop somehow.

> I remember that someone reported it being Debian specific snd-seq-oss
> loading stuff.

There is also additional information here:
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=660803

--
Damien Wyart

2013-07-16 08:28:18

by Philipp Hahn

[permalink] [raw]
Subject: Re: [alsa-devel] [BUG] 3.10.[01] modprobe snd-... hangs

Hello,

Am Dienstag 16 Juli 2013, 08:43:36 schrieb Takashi Iwai:
> At Tue, 16 Jul 2013 15:11:51 +0930, Rusty Russell wrote:
> > Philipp Matthias Hahn <[email protected]> writes:
> > > My x86_64 systems has some trouble loading some ALSA snd-* modules since
> > > the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
> > > loading snd-intel-hda and snd-audio-usb by hand still works.
> >
> > Not a known problem to me, at least. Perhaps it's a dep loop somehow.
>
> I remember that someone reported it being Debian specific snd-seq-oss
> loading stuff.

FYI: "oss-compat" is installed.

> > > ...
> > > 1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
> > > 1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq
> >
> > This was first, and it's waiting. Which means it must be doing
> > something weird, because snd_seq_oss is loading now:
> >
> > > snd_seq_oss 33717 1 - Loading 0xffffffffa041b000
> >
> > Perhaps in the tangle of modprobe install commands somewhere this gets
> > invoked?
>
> Likely, but I wonder what triggered a bug suddenly on 3.10.
> There is absolutely no change in sound/core/seq/*, and through a quick
> look, I couldn't find any suspicious change in kernel/module.c that
> may lead to this problem between 3.9 and 3.10.
>
> Philipp, can you get a sysrq-T trace while the stall?

I've finally been able to reducte the number of processes to get a full trace; see attached file.

Please note that in this case the proprietary "nvidia" module was loaded, since I currently onyl have remove access to the machine.
The original trace from yesterday happend without the nvidia module ever being loaded.

Am Dienstag 16 Juli 2013, 08:42:35 schrieb Lucas De Marchi:
> On Tue, Jul 16, 2013 at 2:41 AM, Rusty Russell <[email protected]> wrote:
> First thing to check is the /etc/modprobe.d/*.conf file that contains
> these install commands. Did they change besides the kernel upgrade?

Not that I know of: Booting 3.9.9 works fine, 3.10.x shows the problem.

...
> Philipp, which kernel are you upgrading from?
I just upgraded from 3.9.9 to 3.10.0; also tried 3.10.1 which did not improve the situation.

> I don't see anything to
> blame in the changes for the past releases. Any chance a bad entry in
> your .conf was added too? You may want to paste the output of modprobe
> -c, at least until "# End of configuration files. Dumping indexes
> now:"

blacklist snd_pcsp
blacklist arkfb
blacklist aty128fb
blacklist atyfb
blacklist radeonfb
blacklist cirrusfb
blacklist cyber2000fb
blacklist gx1fb
blacklist gxfb
blacklist kyrofb
blacklist matroxfb_base
blacklist mb862xxfb
blacklist neofb
blacklist nvidiafb
blacklist pm2fb
blacklist pm3fb
blacklist s3fb
blacklist savagefb
blacklist sisfb
blacklist tdfxfb
blacklist tridentfb
blacklist viafb
blacklist vt8623fb
blacklist garmin_gps
blacklist nouveau
install binfmt_0000 /bin/true
install sound_slot_0 /sbin/modprobe snd-card-0
install sound_slot_1 /sbin/modprobe snd-card-1
install sound_slot_2 /sbin/modprobe snd-card-2
install sound_slot_3 /sbin/modprobe snd-card-3
install sound_slot_4 /sbin/modprobe snd-card-4
install sound_slot_5 /sbin/modprobe snd-card-5
install sound_slot_6 /sbin/modprobe snd-card-6
install sound_slot_7 /sbin/modprobe snd-card-7
install snd /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd-ioctl32 ; /sbin/modprobe --quiet snd-seq ; : ; }
install snd_rawmidi /sbin/modprobe --ignore-install snd-rawmidi && { /sbin/modprobe --quiet snd-seq-midi ; : ; }
install snd_emu10k1 /sbin/modprobe --ignore-install snd-emu10k1 && { /sbin/modprobe --quiet snd-emu10k1-synth ; : ; }
alias net_pf_16_proto_1 wire
alias net_pf_16_proto_3 ip_queue
alias net_pf_16_proto_8 scsi_transport_iscsi
alias net_pf_16_proto_9 audit
alias net_pf_16_proto_11 cn
alias net_pf_16_proto_13 ip6_queue
alias binfmt_204 binfmt_aout
alias binfmt_263 binfmt_aout
alias binfmt_264 binfmt_aout
alias binfmt_267 binfmt_aout
alias binfmt_387 binfmt_aout
alias block_major_3_* ide_generic
alias block_major_22_* ide_generic
alias block_major_33_* ide_generic
alias block_major_34_* ide_generic
alias block_major_37_* ide_tape
alias block_major_44_* ftl
alias block_major_46_* pcd
alias block_major_47_* pf
alias block_major_56_* ide_generic
alias block_major_57_* ide_generic
alias block_major_58_* lvm_mod
alias block_major_88_* ide_generic
alias block_major_89_* ide_generic
alias block_major_90_* ide_generic
alias block_major_91_* ide_generic
alias block_major_93_* nftl
alias block_major_97_* pg
alias char_major_10_1 psmouse
alias char_major_10_139 openprom
alias char_major_10_157 applicom
alias char_major_10_181 toshiba
alias char_major_10_183 hw_random
alias char_major_10_187 irnet
alias char_major_10_189 ussp
alias char_major_10_250 hci_vhci
alias char_major_13_0 joydev
alias char_major_13_1 joydev
alias char_major_13_2 joydev
alias char_major_13_3 joydev
alias char_major_13_32 mousedev
alias char_major_13_33 mousedev
alias char_major_13_34 mousedev
alias char_major_13_35 mousedev
alias char_major_13_63 mousedev
alias char_major_13_64 evdev
alias char_major_13_65 evdev
alias char_major_13_66 evdev
alias char_major_13_67 evdev
alias char_major_19_* cyclades
alias char_major_20_* cyclades
alias char_major_22_* pcxx
alias char_major_23_* pcxx
alias char_major_27_* ftape
alias char_major_34_* scc
alias char_major_35_* tclmidi
alias char_major_48_* riscom8
alias char_major_49_* riscom8
alias char_major_57_* esp
alias char_major_58_* esp
alias char_major_63_* kdebug
alias char_major_67_* coda
alias char_major_75_* specialix
alias char_major_76_* specialix
alias char_major_81_* videodev
alias char_major_83_* vtx
alias char_major_89_* i2c_dev
alias char_major_90_* mtdchar
alias char_major_96_* pt
alias char_major_97_* pg
alias char_major_107_* 3dfx
alias char_major_109_* lvm_mod
alias char_major_166_* cdc_acm
alias char_major_171_0 raw1394
alias char_major_171_1 video1394
alias char_major_171_2 dv1394
alias char_major_171_3 amdtp
alias char_major_180_* usbcore
alias char_major_195_* nvidia
alias char_major_200_* vxspec
alias char_major_202_* msr
alias char_major_203_* cpuid
alias char_major_206_* osst
alias char_major_208_* ussp
alias char_major_227_* tub3270
alias bt_proto_7 avdtp
alias cipcb0 cipcb
alias cipcb1 cipcb
alias cipcb2 cipcb
alias cipcb3 cipcb
alias dummy0 dummy
alias dummy1 dummy
alias plip0 plip
alias plip1 plip
alias slip0 slip
alias slip1 slip
alias tunl0 ipip
alias gre0 ip_gre
alias usbdevfs usbcore
alias char_major_195* nvidia
options snd_pcsp index=-2
options snd_usb_audio index=-2
options bt87x index=-2
options cx88_alsa index=-2
options snd_atiixp_modem index=-2
options snd_intel8x0m index=-2
options snd_via82xx_modem index=-2
options snd_hda_intel model=6stack-dig index=0
options snd_usb_audio index=1
options dvb_ttpci adapter_nr=1
options budget_ci adapter_nr=0
options nbd max_part=15
options nvidia NVreg_DeviceFileUID=0 NVreg_DeviceFileGID=44 NVreg_DeviceFileMode=0660
options libata force=noncq
options systemd log_target=kmsg
softdep uhci_hcd pre: ehci-hcd
softdep ohci_hcd pre: ehci-hcd
softdep snd_pcm post: snd-pcm-oss
softdep snd_mixer post: snd-mixer-oss
softdep snd_seq post: snd-seq-midi snd-seq-oss

# End of configuration files. Dumping indexes now:


Sincerely
Philipp
--
Philipp Hahn <[email protected]>


Attachments:
bug.snd.dmesg (122.80 kB)

2013-07-16 10:28:25

by Takashi Iwai

[permalink] [raw]
Subject: Re: [alsa-devel] [BUG] 3.10.[01] modprobe snd-... hangs

At Tue, 16 Jul 2013 10:28:02 +0200,
Philipp Hahn wrote:
>
> Hello,
>
> Am Dienstag 16 Juli 2013, 08:43:36 schrieb Takashi Iwai:
> > At Tue, 16 Jul 2013 15:11:51 +0930, Rusty Russell wrote:
> > > Philipp Matthias Hahn <[email protected]> writes:
> > > > My x86_64 systems has some trouble loading some ALSA snd-* modules since
> > > > the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
> > > > loading snd-intel-hda and snd-audio-usb by hand still works.
> > >
> > > Not a known problem to me, at least. Perhaps it's a dep loop somehow.
> >
> > I remember that someone reported it being Debian specific snd-seq-oss
> > loading stuff.
>
> FYI: "oss-compat" is installed.
>
> > > > ...
> > > > 1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
> > > > 1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq
> > >
> > > This was first, and it's waiting. Which means it must be doing
> > > something weird, because snd_seq_oss is loading now:
> > >
> > > > snd_seq_oss 33717 1 - Loading 0xffffffffa041b000
> > >
> > > Perhaps in the tangle of modprobe install commands somewhere this gets
> > > invoked?
> >
> > Likely, but I wonder what triggered a bug suddenly on 3.10.
> > There is absolutely no change in sound/core/seq/*, and through a quick
> > look, I couldn't find any suspicious change in kernel/module.c that
> > may lead to this problem between 3.9 and 3.10.
> >
> > Philipp, can you get a sysrq-T trace while the stall?
>
> I've finally been able to reducte the number of processes to get a full trace; see attached file.
>
> Please note that in this case the proprietary "nvidia" module was loaded, since I currently onyl have remove access to the machine.
> The original trace from yesterday happend without the nvidia module ever being loaded.
>
> Am Dienstag 16 Juli 2013, 08:42:35 schrieb Lucas De Marchi:
> > On Tue, Jul 16, 2013 at 2:41 AM, Rusty Russell <[email protected]> wrote:
> > First thing to check is the /etc/modprobe.d/*.conf file that contains
> > these install commands. Did they change besides the kernel upgrade?
>
> Not that I know of: Booting 3.9.9 works fine, 3.10.x shows the problem.
>
> ...
> > Philipp, which kernel are you upgrading from?
> I just upgraded from 3.9.9 to 3.10.0; also tried 3.10.1 which did not improve the situation.

Could you check the patch below? It makes the code path involving
with request_module asynchronous.


thanks,

Takashi

---
From: Takashi Iwai <[email protected]>
Subject: [PATCH] ALSA: seq-oss: Initialize MIDI clients asynchronously

The recent report showed that the initial registration of OSS
sequencer clients stuck at loading the sound modules, which involves
with request_module() at the init phase. As a workaround, call the
registration part asynchronously. (And, this is a better approache
irrespective of the hang fix.)

Reported-by: Philipp Matthias Hahn <[email protected]>
Cc: <[email protected]>
Signed-off-by: Takashi Iwai <[email protected]>
---
sound/core/seq/oss/seq_oss_init.c | 16 +++++++++++++---
sound/core/seq/oss/seq_oss_midi.c | 2 +-
2 files changed, 14 insertions(+), 4 deletions(-)

diff --git a/sound/core/seq/oss/seq_oss_init.c b/sound/core/seq/oss/seq_oss_init.c
index e3cb46f..b3f39b5 100644
--- a/sound/core/seq/oss/seq_oss_init.c
+++ b/sound/core/seq/oss/seq_oss_init.c
@@ -31,6 +31,7 @@
#include <linux/export.h>
#include <linux/moduleparam.h>
#include <linux/slab.h>
+#include <linux/workqueue.h>

/*
* common variables
@@ -60,6 +61,14 @@ static void free_devinfo(void *private);
#define call_ctl(type,rec) snd_seq_kernel_client_ctl(system_client, type, rec)


+/* call snd_seq_oss_midi_lookup_ports() asynchronously */
+static void async_call_lookup_ports(struct work_struct *work)
+{
+ snd_seq_oss_midi_lookup_ports(system_client);
+}
+
+static DECLARE_WORK(async_lookup_work, async_call_lookup_ports);
+
/*
* create sequencer client for OSS sequencer
*/
@@ -85,9 +94,6 @@ snd_seq_oss_create_client(void)
system_client = rc;
debug_printk(("new client = %d\n", rc));

- /* look up midi devices */
- snd_seq_oss_midi_lookup_ports(system_client);
-
/* create annoucement receiver port */
memset(port, 0, sizeof(*port));
strcpy(port->name, "Receiver");
@@ -115,6 +121,9 @@ snd_seq_oss_create_client(void)
}
rc = 0;

+ /* look up midi devices */
+ schedule_work(&async_lookup_work);
+
__error:
kfree(port);
return rc;
@@ -160,6 +169,7 @@ receive_announce(struct snd_seq_event *ev, int direct, void *private, int atomic
int
snd_seq_oss_delete_client(void)
{
+ cancel_work_sync(&async_lookup_work);
if (system_client >= 0)
snd_seq_delete_kernel_client(system_client);

diff --git a/sound/core/seq/oss/seq_oss_midi.c b/sound/core/seq/oss/seq_oss_midi.c
index 677dc84..862d8489 100644
--- a/sound/core/seq/oss/seq_oss_midi.c
+++ b/sound/core/seq/oss/seq_oss_midi.c
@@ -72,7 +72,7 @@ static int send_midi_event(struct seq_oss_devinfo *dp, struct snd_seq_event *ev,
* look up the existing ports
* this looks a very exhausting job.
*/
-int __init
+int
snd_seq_oss_midi_lookup_ports(int client)
{
struct snd_seq_client_info *clinfo;
--
1.8.3.1

2013-07-16 16:03:37

by Lucas De Marchi

[permalink] [raw]
Subject: Re: [alsa-devel] [BUG] 3.10.[01] modprobe snd-... hangs

On Tue, Jul 16, 2013 at 5:28 AM, Philipp Hahn <[email protected]> wrote:
> Hello,
>
> Am Dienstag 16 Juli 2013, 08:43:36 schrieb Takashi Iwai:
>> At Tue, 16 Jul 2013 15:11:51 +0930, Rusty Russell wrote:
>> > Philipp Matthias Hahn <[email protected]> writes:
>> > > My x86_64 systems has some trouble loading some ALSA snd-* modules since
>> > > the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
>> > > loading snd-intel-hda and snd-audio-usb by hand still works.
>> >
>> > Not a known problem to me, at least. Perhaps it's a dep loop somehow.
>>
>> I remember that someone reported it being Debian specific snd-seq-oss
>> loading stuff.
>
> FYI: "oss-compat" is installed.
>
>> > > ...
>> > > 1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
>> > > 1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq
>> >
>> > This was first, and it's waiting. Which means it must be doing
>> > something weird, because snd_seq_oss is loading now:
>> >
>> > > snd_seq_oss 33717 1 - Loading 0xffffffffa041b000
>> >
>> > Perhaps in the tangle of modprobe install commands somewhere this gets
>> > invoked?
>>
>> Likely, but I wonder what triggered a bug suddenly on 3.10.
>> There is absolutely no change in sound/core/seq/*, and through a quick
>> look, I couldn't find any suspicious change in kernel/module.c that
>> may lead to this problem between 3.9 and 3.10.
>>
>> Philipp, can you get a sysrq-T trace while the stall?
>
> I've finally been able to reducte the number of processes to get a full trace; see attached file.
>
> Please note that in this case the proprietary "nvidia" module was loaded, since I currently onyl have remove access to the machine.
> The original trace from yesterday happend without the nvidia module ever being loaded.
>
> Am Dienstag 16 Juli 2013, 08:42:35 schrieb Lucas De Marchi:
>> On Tue, Jul 16, 2013 at 2:41 AM, Rusty Russell <[email protected]> wrote:
>> First thing to check is the /etc/modprobe.d/*.conf file that contains
>> these install commands. Did they change besides the kernel upgrade?
>
> Not that I know of: Booting 3.9.9 works fine, 3.10.x shows the problem.

Then one possible explanation is that in 3.9.9 you don't have some of
the modules causing this problem

>
> ...
>> Philipp, which kernel are you upgrading from?
> I just upgraded from 3.9.9 to 3.10.0; also tried 3.10.1 which did not improve the situation.
>
>> I don't see anything to
>> blame in the changes for the past releases. Any chance a bad entry in
>> your .conf was added too? You may want to paste the output of modprobe
>> -c, at least until "# End of configuration files. Dumping indexes
>> now:"
>
> blacklist snd_pcsp
> blacklist arkfb
> blacklist aty128fb
> blacklist atyfb
> blacklist radeonfb
> blacklist cirrusfb
> blacklist cyber2000fb
> blacklist gx1fb
> blacklist gxfb
> blacklist kyrofb
> blacklist matroxfb_base
> blacklist mb862xxfb
> blacklist neofb
> blacklist nvidiafb
> blacklist pm2fb
> blacklist pm3fb
> blacklist s3fb
> blacklist savagefb
> blacklist sisfb
> blacklist tdfxfb
> blacklist tridentfb
> blacklist viafb
> blacklist vt8623fb
> blacklist garmin_gps
> blacklist nouveau
> install binfmt_0000 /bin/true
> install sound_slot_0 /sbin/modprobe snd-card-0
> install sound_slot_1 /sbin/modprobe snd-card-1
> install sound_slot_2 /sbin/modprobe snd-card-2
> install sound_slot_3 /sbin/modprobe snd-card-3
> install sound_slot_4 /sbin/modprobe snd-card-4
> install sound_slot_5 /sbin/modprobe snd-card-5
> install sound_slot_6 /sbin/modprobe snd-card-6
> install sound_slot_7 /sbin/modprobe snd-card-7
> install snd /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd-ioctl32 ; /sbin/modprobe --quiet snd-seq ; : ; }
> install snd_rawmidi /sbin/modprobe --ignore-install snd-rawmidi && { /sbin/modprobe --quiet snd-seq-midi ; : ; }
> install snd_emu10k1 /sbin/modprobe --ignore-install snd-emu10k1 && { /sbin/modprobe --quiet snd-emu10k1-synth ; : ; }
> alias net_pf_16_proto_1 wire
> alias net_pf_16_proto_3 ip_queue
> alias net_pf_16_proto_8 scsi_transport_iscsi
> alias net_pf_16_proto_9 audit
> alias net_pf_16_proto_11 cn
> alias net_pf_16_proto_13 ip6_queue
> alias binfmt_204 binfmt_aout
> alias binfmt_263 binfmt_aout
> alias binfmt_264 binfmt_aout
> alias binfmt_267 binfmt_aout
> alias binfmt_387 binfmt_aout
> alias block_major_3_* ide_generic
> alias block_major_22_* ide_generic
> alias block_major_33_* ide_generic
> alias block_major_34_* ide_generic
> alias block_major_37_* ide_tape
> alias block_major_44_* ftl
> alias block_major_46_* pcd
> alias block_major_47_* pf
> alias block_major_56_* ide_generic
> alias block_major_57_* ide_generic
> alias block_major_58_* lvm_mod
> alias block_major_88_* ide_generic
> alias block_major_89_* ide_generic
> alias block_major_90_* ide_generic
> alias block_major_91_* ide_generic
> alias block_major_93_* nftl
> alias block_major_97_* pg
> alias char_major_10_1 psmouse
> alias char_major_10_139 openprom
> alias char_major_10_157 applicom
> alias char_major_10_181 toshiba
> alias char_major_10_183 hw_random
> alias char_major_10_187 irnet
> alias char_major_10_189 ussp
> alias char_major_10_250 hci_vhci
> alias char_major_13_0 joydev
> alias char_major_13_1 joydev
> alias char_major_13_2 joydev
> alias char_major_13_3 joydev
> alias char_major_13_32 mousedev
> alias char_major_13_33 mousedev
> alias char_major_13_34 mousedev
> alias char_major_13_35 mousedev
> alias char_major_13_63 mousedev
> alias char_major_13_64 evdev
> alias char_major_13_65 evdev
> alias char_major_13_66 evdev
> alias char_major_13_67 evdev
> alias char_major_19_* cyclades
> alias char_major_20_* cyclades
> alias char_major_22_* pcxx
> alias char_major_23_* pcxx
> alias char_major_27_* ftape
> alias char_major_34_* scc
> alias char_major_35_* tclmidi
> alias char_major_48_* riscom8
> alias char_major_49_* riscom8
> alias char_major_57_* esp
> alias char_major_58_* esp
> alias char_major_63_* kdebug
> alias char_major_67_* coda
> alias char_major_75_* specialix
> alias char_major_76_* specialix
> alias char_major_81_* videodev
> alias char_major_83_* vtx
> alias char_major_89_* i2c_dev
> alias char_major_90_* mtdchar
> alias char_major_96_* pt
> alias char_major_97_* pg
> alias char_major_107_* 3dfx
> alias char_major_109_* lvm_mod
> alias char_major_166_* cdc_acm
> alias char_major_171_0 raw1394
> alias char_major_171_1 video1394
> alias char_major_171_2 dv1394
> alias char_major_171_3 amdtp
> alias char_major_180_* usbcore
> alias char_major_195_* nvidia
> alias char_major_200_* vxspec
> alias char_major_202_* msr
> alias char_major_203_* cpuid
> alias char_major_206_* osst
> alias char_major_208_* ussp
> alias char_major_227_* tub3270
> alias bt_proto_7 avdtp
> alias cipcb0 cipcb
> alias cipcb1 cipcb
> alias cipcb2 cipcb
> alias cipcb3 cipcb
> alias dummy0 dummy
> alias dummy1 dummy
> alias plip0 plip
> alias plip1 plip
> alias slip0 slip
> alias slip1 slip
> alias tunl0 ipip
> alias gre0 ip_gre
> alias usbdevfs usbcore
> alias char_major_195* nvidia
> options snd_pcsp index=-2
> options snd_usb_audio index=-2
> options bt87x index=-2
> options cx88_alsa index=-2
> options snd_atiixp_modem index=-2
> options snd_intel8x0m index=-2
> options snd_via82xx_modem index=-2
> options snd_hda_intel model=6stack-dig index=0
> options snd_usb_audio index=1
> options dvb_ttpci adapter_nr=1
> options budget_ci adapter_nr=0
> options nbd max_part=15
> options nvidia NVreg_DeviceFileUID=0 NVreg_DeviceFileGID=44 NVreg_DeviceFileMode=0660
> options libata force=noncq
> options systemd log_target=kmsg
> softdep uhci_hcd pre: ehci-hcd
> softdep ohci_hcd pre: ehci-hcd
> softdep snd_pcm post: snd-pcm-oss
> softdep snd_mixer post: snd-mixer-oss
> softdep snd_seq post: snd-seq-midi snd-seq-oss


hum... it looks like a loop between the modprobe calls and the
request_module(), done in snd_seq's init. The request_module() call
will end up trying to load snd_seq again and it will remain waiting on
kernel/module.c:add_unformed_module().

In kmod we don't trust a COMING state on sysfs to avoid calling
(f)init_module() because a) the previous call may fail and b) it's
racy.

Changing the request_module() in the module to be async would solve
the problem (what Takashi Iwai did)... but this has been a
little controversial in the past. Rusty, what do you think? Maybe in
kmod we can take the COMING state into consideration for
*dependencies*? Or is moving that call to a worker acceptable?


Lucas De Marchi

2013-07-16 21:43:38

by Philipp Hahn

[permalink] [raw]
Subject: Re: [alsa-devel] [BUG] 3.10.[01] modprobe snd-... hangs

Hello,

On Tue, Jul 16, 2013 at 12:29:38PM +0200, Takashi Iwai wrote:
> Could you check the patch below? It makes the code path involving
> with request_module asynchronous.

With the patch applied all modules were loaded successfully: no hanging
modprobe processes anymore.

Thank you for your support.

...
> From: Takashi Iwai <[email protected]>
> Subject: [PATCH] ALSA: seq-oss: Initialize MIDI clients asynchronously
>
> The recent report showed that the initial registration of OSS
> sequencer clients stuck at loading the sound modules, which involves
> with request_module() at the init phase. As a workaround, call the
> registration part asynchronously. (And, this is a better approache
> irrespective of the hang fix.)
>
> Reported-by: Philipp Matthias Hahn <[email protected]>
> Cc: <[email protected]>
> Signed-off-by: Takashi Iwai <[email protected]>
> ---
> sound/core/seq/oss/seq_oss_init.c | 16 +++++++++++++---
> sound/core/seq/oss/seq_oss_midi.c | 2 +-
> 2 files changed, 14 insertions(+), 4 deletions(-)
>
> diff --git a/sound/core/seq/oss/seq_oss_init.c b/sound/core/seq/oss/seq_oss_init.c
> index e3cb46f..b3f39b5 100644

BYtE
Philipp
--
/ / (_)__ __ ____ __ Philipp Hahn
/ /__/ / _ \/ // /\ \/ /
/____/_/_//_/\_,_/ /_/\_\ [email protected]

2013-07-17 01:04:18

by Rusty Russell

[permalink] [raw]
Subject: Re: [alsa-devel] [BUG] 3.10.[01] modprobe snd-... hangs

Lucas De Marchi <[email protected]> writes:
> On Tue, Jul 16, 2013 at 5:28 AM, Philipp Hahn <[email protected]> wrote:
>> Hello,
>>
>> Am Dienstag 16 Juli 2013, 08:43:36 schrieb Takashi Iwai:
>>> At Tue, 16 Jul 2013 15:11:51 +0930, Rusty Russell wrote:
>>> > Philipp Matthias Hahn <[email protected]> writes:
>>> > > My x86_64 systems has some trouble loading some ALSA snd-* modules since
>>> > > the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
>>> > > loading snd-intel-hda and snd-audio-usb by hand still works.
>>> >
>>> > Not a known problem to me, at least. Perhaps it's a dep loop somehow.
>>>
>>> I remember that someone reported it being Debian specific snd-seq-oss
>>> loading stuff.
>>
>> FYI: "oss-compat" is installed.
>>
>>> > > ...
>>> > > 1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
>>> > > 1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq
>>> >
>>> > This was first, and it's waiting. Which means it must be doing
>>> > something weird, because snd_seq_oss is loading now:
>>> >
>>> > > snd_seq_oss 33717 1 - Loading 0xffffffffa041b000
>>> >
>>> > Perhaps in the tangle of modprobe install commands somewhere this gets
>>> > invoked?
>>>
>>> Likely, but I wonder what triggered a bug suddenly on 3.10.
>>> There is absolutely no change in sound/core/seq/*, and through a quick
>>> look, I couldn't find any suspicious change in kernel/module.c that
>>> may lead to this problem between 3.9 and 3.10.
>>>
>>> Philipp, can you get a sysrq-T trace while the stall?
>>
>> I've finally been able to reducte the number of processes to get a full trace; see attached file.
>>
>> Please note that in this case the proprietary "nvidia" module was loaded, since I currently onyl have remove access to the machine.
>> The original trace from yesterday happend without the nvidia module ever being loaded.
>>
>> Am Dienstag 16 Juli 2013, 08:42:35 schrieb Lucas De Marchi:
>>> On Tue, Jul 16, 2013 at 2:41 AM, Rusty Russell <[email protected]> wrote:
>>> First thing to check is the /etc/modprobe.d/*.conf file that contains
>>> these install commands. Did they change besides the kernel upgrade?
>>
>> Not that I know of: Booting 3.9.9 works fine, 3.10.x shows the problem.
>
> Then one possible explanation is that in 3.9.9 you don't have some of
> the modules causing this problem
>
>>
>> ...
>>> Philipp, which kernel are you upgrading from?
>> I just upgraded from 3.9.9 to 3.10.0; also tried 3.10.1 which did not improve the situation.
>>
>>> I don't see anything to
>>> blame in the changes for the past releases. Any chance a bad entry in
>>> your .conf was added too? You may want to paste the output of modprobe
>>> -c, at least until "# End of configuration files. Dumping indexes
>>> now:"
>>
>> blacklist snd_pcsp
>> blacklist arkfb
>> blacklist aty128fb
>> blacklist atyfb
>> blacklist radeonfb
>> blacklist cirrusfb
>> blacklist cyber2000fb
>> blacklist gx1fb
>> blacklist gxfb
>> blacklist kyrofb
>> blacklist matroxfb_base
>> blacklist mb862xxfb
>> blacklist neofb
>> blacklist nvidiafb
>> blacklist pm2fb
>> blacklist pm3fb
>> blacklist s3fb
>> blacklist savagefb
>> blacklist sisfb
>> blacklist tdfxfb
>> blacklist tridentfb
>> blacklist viafb
>> blacklist vt8623fb
>> blacklist garmin_gps
>> blacklist nouveau
>> install binfmt_0000 /bin/true
>> install sound_slot_0 /sbin/modprobe snd-card-0
>> install sound_slot_1 /sbin/modprobe snd-card-1
>> install sound_slot_2 /sbin/modprobe snd-card-2
>> install sound_slot_3 /sbin/modprobe snd-card-3
>> install sound_slot_4 /sbin/modprobe snd-card-4
>> install sound_slot_5 /sbin/modprobe snd-card-5
>> install sound_slot_6 /sbin/modprobe snd-card-6
>> install sound_slot_7 /sbin/modprobe snd-card-7
>> install snd /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd-ioctl32 ; /sbin/modprobe --quiet snd-seq ; : ; }
>> install snd_rawmidi /sbin/modprobe --ignore-install snd-rawmidi && { /sbin/modprobe --quiet snd-seq-midi ; : ; }
>> install snd_emu10k1 /sbin/modprobe --ignore-install snd-emu10k1 && { /sbin/modprobe --quiet snd-emu10k1-synth ; : ; }
>> alias net_pf_16_proto_1 wire
>> alias net_pf_16_proto_3 ip_queue
>> alias net_pf_16_proto_8 scsi_transport_iscsi
>> alias net_pf_16_proto_9 audit
>> alias net_pf_16_proto_11 cn
>> alias net_pf_16_proto_13 ip6_queue
>> alias binfmt_204 binfmt_aout
>> alias binfmt_263 binfmt_aout
>> alias binfmt_264 binfmt_aout
>> alias binfmt_267 binfmt_aout
>> alias binfmt_387 binfmt_aout
>> alias block_major_3_* ide_generic
>> alias block_major_22_* ide_generic
>> alias block_major_33_* ide_generic
>> alias block_major_34_* ide_generic
>> alias block_major_37_* ide_tape
>> alias block_major_44_* ftl
>> alias block_major_46_* pcd
>> alias block_major_47_* pf
>> alias block_major_56_* ide_generic
>> alias block_major_57_* ide_generic
>> alias block_major_58_* lvm_mod
>> alias block_major_88_* ide_generic
>> alias block_major_89_* ide_generic
>> alias block_major_90_* ide_generic
>> alias block_major_91_* ide_generic
>> alias block_major_93_* nftl
>> alias block_major_97_* pg
>> alias char_major_10_1 psmouse
>> alias char_major_10_139 openprom
>> alias char_major_10_157 applicom
>> alias char_major_10_181 toshiba
>> alias char_major_10_183 hw_random
>> alias char_major_10_187 irnet
>> alias char_major_10_189 ussp
>> alias char_major_10_250 hci_vhci
>> alias char_major_13_0 joydev
>> alias char_major_13_1 joydev
>> alias char_major_13_2 joydev
>> alias char_major_13_3 joydev
>> alias char_major_13_32 mousedev
>> alias char_major_13_33 mousedev
>> alias char_major_13_34 mousedev
>> alias char_major_13_35 mousedev
>> alias char_major_13_63 mousedev
>> alias char_major_13_64 evdev
>> alias char_major_13_65 evdev
>> alias char_major_13_66 evdev
>> alias char_major_13_67 evdev
>> alias char_major_19_* cyclades
>> alias char_major_20_* cyclades
>> alias char_major_22_* pcxx
>> alias char_major_23_* pcxx
>> alias char_major_27_* ftape
>> alias char_major_34_* scc
>> alias char_major_35_* tclmidi
>> alias char_major_48_* riscom8
>> alias char_major_49_* riscom8
>> alias char_major_57_* esp
>> alias char_major_58_* esp
>> alias char_major_63_* kdebug
>> alias char_major_67_* coda
>> alias char_major_75_* specialix
>> alias char_major_76_* specialix
>> alias char_major_81_* videodev
>> alias char_major_83_* vtx
>> alias char_major_89_* i2c_dev
>> alias char_major_90_* mtdchar
>> alias char_major_96_* pt
>> alias char_major_97_* pg
>> alias char_major_107_* 3dfx
>> alias char_major_109_* lvm_mod
>> alias char_major_166_* cdc_acm
>> alias char_major_171_0 raw1394
>> alias char_major_171_1 video1394
>> alias char_major_171_2 dv1394
>> alias char_major_171_3 amdtp
>> alias char_major_180_* usbcore
>> alias char_major_195_* nvidia
>> alias char_major_200_* vxspec
>> alias char_major_202_* msr
>> alias char_major_203_* cpuid
>> alias char_major_206_* osst
>> alias char_major_208_* ussp
>> alias char_major_227_* tub3270
>> alias bt_proto_7 avdtp
>> alias cipcb0 cipcb
>> alias cipcb1 cipcb
>> alias cipcb2 cipcb
>> alias cipcb3 cipcb
>> alias dummy0 dummy
>> alias dummy1 dummy
>> alias plip0 plip
>> alias plip1 plip
>> alias slip0 slip
>> alias slip1 slip
>> alias tunl0 ipip
>> alias gre0 ip_gre
>> alias usbdevfs usbcore
>> alias char_major_195* nvidia
>> options snd_pcsp index=-2
>> options snd_usb_audio index=-2
>> options bt87x index=-2
>> options cx88_alsa index=-2
>> options snd_atiixp_modem index=-2
>> options snd_intel8x0m index=-2
>> options snd_via82xx_modem index=-2
>> options snd_hda_intel model=6stack-dig index=0
>> options snd_usb_audio index=1
>> options dvb_ttpci adapter_nr=1
>> options budget_ci adapter_nr=0
>> options nbd max_part=15
>> options nvidia NVreg_DeviceFileUID=0 NVreg_DeviceFileGID=44 NVreg_DeviceFileMode=0660
>> options libata force=noncq
>> options systemd log_target=kmsg
>> softdep uhci_hcd pre: ehci-hcd
>> softdep ohci_hcd pre: ehci-hcd
>> softdep snd_pcm post: snd-pcm-oss
>> softdep snd_mixer post: snd-mixer-oss
>> softdep snd_seq post: snd-seq-midi snd-seq-oss
>
>
> hum... it looks like a loop between the modprobe calls and the
> request_module(), done in snd_seq's init. The request_module() call
> will end up trying to load snd_seq again and it will remain waiting on
> kernel/module.c:add_unformed_module().
>
> In kmod we don't trust a COMING state on sysfs to avoid calling
> (f)init_module() because a) the previous call may fail and b) it's
> racy.

Yes, add_unformed_module makes the same call. I think the answer is
simply "don't do that".

> Changing the request_module() in the module to be async would solve
> the problem (what Takashi Iwai did)... but this has been a
> little controversial in the past. Rusty, what do you think? Maybe in
> kmod we can take the COMING state into consideration for
> *dependencies*? Or is moving that call to a worker acceptable?

I thought about adding a post_init() call for modules for this kind of
thing, but it's actually pretty rare. Open-coding it seems fine.

Cheers,
Rusty.

2013-07-17 07:13:47

by Takashi Iwai

[permalink] [raw]
Subject: Re: [alsa-devel] [BUG] 3.10.[01] modprobe snd-... hangs

At Wed, 17 Jul 2013 09:30:21 +0930,
Rusty Russell wrote:
>
> Lucas De Marchi <[email protected]> writes:
> > On Tue, Jul 16, 2013 at 5:28 AM, Philipp Hahn <[email protected]> wrote:
> >> Hello,
> >>
> >> Am Dienstag 16 Juli 2013, 08:43:36 schrieb Takashi Iwai:
> >>> At Tue, 16 Jul 2013 15:11:51 +0930, Rusty Russell wrote:
> >>> > Philipp Matthias Hahn <[email protected]> writes:
> >>> > > My x86_64 systems has some trouble loading some ALSA snd-* modules since
> >>> > > the upgrade to 3.10.[01]: Several automatic modprobe calls hang, but
> >>> > > loading snd-intel-hda and snd-audio-usb by hand still works.
> >>> >
> >>> > Not a known problem to me, at least. Perhaps it's a dep loop somehow.
> >>>
> >>> I remember that someone reported it being Debian specific snd-seq-oss
> >>> loading stuff.
> >>
> >> FYI: "oss-compat" is installed.
> >>
> >>> > > ...
> >>> > > 1071 ? S 0:00 sh -c /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd
> >>> > > 1080 ? D 0:00 \_ /sbin/modprobe --quiet snd-seq
> >>> >
> >>> > This was first, and it's waiting. Which means it must be doing
> >>> > something weird, because snd_seq_oss is loading now:
> >>> >
> >>> > > snd_seq_oss 33717 1 - Loading 0xffffffffa041b000
> >>> >
> >>> > Perhaps in the tangle of modprobe install commands somewhere this gets
> >>> > invoked?
> >>>
> >>> Likely, but I wonder what triggered a bug suddenly on 3.10.
> >>> There is absolutely no change in sound/core/seq/*, and through a quick
> >>> look, I couldn't find any suspicious change in kernel/module.c that
> >>> may lead to this problem between 3.9 and 3.10.
> >>>
> >>> Philipp, can you get a sysrq-T trace while the stall?
> >>
> >> I've finally been able to reducte the number of processes to get a full trace; see attached file.
> >>
> >> Please note that in this case the proprietary "nvidia" module was loaded, since I currently onyl have remove access to the machine.
> >> The original trace from yesterday happend without the nvidia module ever being loaded.
> >>
> >> Am Dienstag 16 Juli 2013, 08:42:35 schrieb Lucas De Marchi:
> >>> On Tue, Jul 16, 2013 at 2:41 AM, Rusty Russell <[email protected]> wrote:
> >>> First thing to check is the /etc/modprobe.d/*.conf file that contains
> >>> these install commands. Did they change besides the kernel upgrade?
> >>
> >> Not that I know of: Booting 3.9.9 works fine, 3.10.x shows the problem.
> >
> > Then one possible explanation is that in 3.9.9 you don't have some of
> > the modules causing this problem
> >
> >>
> >> ...
> >>> Philipp, which kernel are you upgrading from?
> >> I just upgraded from 3.9.9 to 3.10.0; also tried 3.10.1 which did not improve the situation.
> >>
> >>> I don't see anything to
> >>> blame in the changes for the past releases. Any chance a bad entry in
> >>> your .conf was added too? You may want to paste the output of modprobe
> >>> -c, at least until "# End of configuration files. Dumping indexes
> >>> now:"
> >>
> >> blacklist snd_pcsp
> >> blacklist arkfb
> >> blacklist aty128fb
> >> blacklist atyfb
> >> blacklist radeonfb
> >> blacklist cirrusfb
> >> blacklist cyber2000fb
> >> blacklist gx1fb
> >> blacklist gxfb
> >> blacklist kyrofb
> >> blacklist matroxfb_base
> >> blacklist mb862xxfb
> >> blacklist neofb
> >> blacklist nvidiafb
> >> blacklist pm2fb
> >> blacklist pm3fb
> >> blacklist s3fb
> >> blacklist savagefb
> >> blacklist sisfb
> >> blacklist tdfxfb
> >> blacklist tridentfb
> >> blacklist viafb
> >> blacklist vt8623fb
> >> blacklist garmin_gps
> >> blacklist nouveau
> >> install binfmt_0000 /bin/true
> >> install sound_slot_0 /sbin/modprobe snd-card-0
> >> install sound_slot_1 /sbin/modprobe snd-card-1
> >> install sound_slot_2 /sbin/modprobe snd-card-2
> >> install sound_slot_3 /sbin/modprobe snd-card-3
> >> install sound_slot_4 /sbin/modprobe snd-card-4
> >> install sound_slot_5 /sbin/modprobe snd-card-5
> >> install sound_slot_6 /sbin/modprobe snd-card-6
> >> install sound_slot_7 /sbin/modprobe snd-card-7
> >> install snd /sbin/modprobe --ignore-install snd && { /sbin/modprobe --quiet snd-ioctl32 ; /sbin/modprobe --quiet snd-seq ; : ; }
> >> install snd_rawmidi /sbin/modprobe --ignore-install snd-rawmidi && { /sbin/modprobe --quiet snd-seq-midi ; : ; }
> >> install snd_emu10k1 /sbin/modprobe --ignore-install snd-emu10k1 && { /sbin/modprobe --quiet snd-emu10k1-synth ; : ; }
> >> alias net_pf_16_proto_1 wire
> >> alias net_pf_16_proto_3 ip_queue
> >> alias net_pf_16_proto_8 scsi_transport_iscsi
> >> alias net_pf_16_proto_9 audit
> >> alias net_pf_16_proto_11 cn
> >> alias net_pf_16_proto_13 ip6_queue
> >> alias binfmt_204 binfmt_aout
> >> alias binfmt_263 binfmt_aout
> >> alias binfmt_264 binfmt_aout
> >> alias binfmt_267 binfmt_aout
> >> alias binfmt_387 binfmt_aout
> >> alias block_major_3_* ide_generic
> >> alias block_major_22_* ide_generic
> >> alias block_major_33_* ide_generic
> >> alias block_major_34_* ide_generic
> >> alias block_major_37_* ide_tape
> >> alias block_major_44_* ftl
> >> alias block_major_46_* pcd
> >> alias block_major_47_* pf
> >> alias block_major_56_* ide_generic
> >> alias block_major_57_* ide_generic
> >> alias block_major_58_* lvm_mod
> >> alias block_major_88_* ide_generic
> >> alias block_major_89_* ide_generic
> >> alias block_major_90_* ide_generic
> >> alias block_major_91_* ide_generic
> >> alias block_major_93_* nftl
> >> alias block_major_97_* pg
> >> alias char_major_10_1 psmouse
> >> alias char_major_10_139 openprom
> >> alias char_major_10_157 applicom
> >> alias char_major_10_181 toshiba
> >> alias char_major_10_183 hw_random
> >> alias char_major_10_187 irnet
> >> alias char_major_10_189 ussp
> >> alias char_major_10_250 hci_vhci
> >> alias char_major_13_0 joydev
> >> alias char_major_13_1 joydev
> >> alias char_major_13_2 joydev
> >> alias char_major_13_3 joydev
> >> alias char_major_13_32 mousedev
> >> alias char_major_13_33 mousedev
> >> alias char_major_13_34 mousedev
> >> alias char_major_13_35 mousedev
> >> alias char_major_13_63 mousedev
> >> alias char_major_13_64 evdev
> >> alias char_major_13_65 evdev
> >> alias char_major_13_66 evdev
> >> alias char_major_13_67 evdev
> >> alias char_major_19_* cyclades
> >> alias char_major_20_* cyclades
> >> alias char_major_22_* pcxx
> >> alias char_major_23_* pcxx
> >> alias char_major_27_* ftape
> >> alias char_major_34_* scc
> >> alias char_major_35_* tclmidi
> >> alias char_major_48_* riscom8
> >> alias char_major_49_* riscom8
> >> alias char_major_57_* esp
> >> alias char_major_58_* esp
> >> alias char_major_63_* kdebug
> >> alias char_major_67_* coda
> >> alias char_major_75_* specialix
> >> alias char_major_76_* specialix
> >> alias char_major_81_* videodev
> >> alias char_major_83_* vtx
> >> alias char_major_89_* i2c_dev
> >> alias char_major_90_* mtdchar
> >> alias char_major_96_* pt
> >> alias char_major_97_* pg
> >> alias char_major_107_* 3dfx
> >> alias char_major_109_* lvm_mod
> >> alias char_major_166_* cdc_acm
> >> alias char_major_171_0 raw1394
> >> alias char_major_171_1 video1394
> >> alias char_major_171_2 dv1394
> >> alias char_major_171_3 amdtp
> >> alias char_major_180_* usbcore
> >> alias char_major_195_* nvidia
> >> alias char_major_200_* vxspec
> >> alias char_major_202_* msr
> >> alias char_major_203_* cpuid
> >> alias char_major_206_* osst
> >> alias char_major_208_* ussp
> >> alias char_major_227_* tub3270
> >> alias bt_proto_7 avdtp
> >> alias cipcb0 cipcb
> >> alias cipcb1 cipcb
> >> alias cipcb2 cipcb
> >> alias cipcb3 cipcb
> >> alias dummy0 dummy
> >> alias dummy1 dummy
> >> alias plip0 plip
> >> alias plip1 plip
> >> alias slip0 slip
> >> alias slip1 slip
> >> alias tunl0 ipip
> >> alias gre0 ip_gre
> >> alias usbdevfs usbcore
> >> alias char_major_195* nvidia
> >> options snd_pcsp index=-2
> >> options snd_usb_audio index=-2
> >> options bt87x index=-2
> >> options cx88_alsa index=-2
> >> options snd_atiixp_modem index=-2
> >> options snd_intel8x0m index=-2
> >> options snd_via82xx_modem index=-2
> >> options snd_hda_intel model=6stack-dig index=0
> >> options snd_usb_audio index=1
> >> options dvb_ttpci adapter_nr=1
> >> options budget_ci adapter_nr=0
> >> options nbd max_part=15
> >> options nvidia NVreg_DeviceFileUID=0 NVreg_DeviceFileGID=44 NVreg_DeviceFileMode=0660
> >> options libata force=noncq
> >> options systemd log_target=kmsg
> >> softdep uhci_hcd pre: ehci-hcd
> >> softdep ohci_hcd pre: ehci-hcd
> >> softdep snd_pcm post: snd-pcm-oss
> >> softdep snd_mixer post: snd-mixer-oss
> >> softdep snd_seq post: snd-seq-midi snd-seq-oss
> >
> >
> > hum... it looks like a loop between the modprobe calls and the
> > request_module(), done in snd_seq's init. The request_module() call
> > will end up trying to load snd_seq again and it will remain waiting on
> > kernel/module.c:add_unformed_module().
> >
> > In kmod we don't trust a COMING state on sysfs to avoid calling
> > (f)init_module() because a) the previous call may fail and b) it's
> > racy.
>
> Yes, add_unformed_module makes the same call. I think the answer is
> simply "don't do that".
>
> > Changing the request_module() in the module to be async would solve
> > the problem (what Takashi Iwai did)... but this has been a
> > little controversial in the past. Rusty, what do you think? Maybe in
> > kmod we can take the COMING state into consideration for
> > *dependencies*? Or is moving that call to a worker acceptable?
>
> I thought about adding a post_init() call for modules for this kind of
> thing, but it's actually pretty rare. Open-coding it seems fine.

The conversion to async call would be a problem if it needs to change
the code flow largely. In this particular case, however, it's no big
problem (as little as the patch size is), so I'm going to apply my
patch as is for now.


thanks,

Takashi