diff mbox

[GIT,PULL,9/9] ARM: tegra: Default configuration updates for v4.3-rc1

Message ID CAMAWPa_rus4z+Sg3Uff7ndqrpB8dF1c1rQBVQ9r7vXh6PFcVkQ@mail.gmail.com (mailing list archive)
State New, archived
Headers show

Commit Message

Kevin Hilman Sept. 10, 2015, 9:29 p.m. UTC 
On Thu, Sep 3, 2015 at 4:08 PM, Tyler Baker <tyler.baker@linaro.org> wrote:
> Hi Thierry,
>
> On 19 August 2015 at 03:33, Thierry Reding <thierry.reding@gmail.com> wrote:
>> On Wed, Aug 19, 2015 at 11:48:44AM +0200, Sjoerd Simons wrote:
>>> On Wed, 2015-08-19 at 11:14 +0200, Thierry Reding wrote:
>>> > On Tue, Aug 18, 2015 at 03:30:41PM -0700, Tyler Baker wrote:
>>> > > Hi Theirry,
>>> > >
>>> > >
>>> > > This isn't where the story ends unfortunately. The collabora lab
>>> > > also
>>> > > has a jetson-tk1, booted in the same manner, which boots next
>>> > > -20150818
>>> > > fine[4]. The only differences I can spot in the two boot logs is
>>> > > that
>>> > > the collabora board is using an older version of u-boot, where as
>>> > > my
>>> > > board is using a newer version. U-Boot 2015.01-00231-gab77f24-dirty
>>> > > (Good) vs U-Boot 2015.07-00130-gb217c89 (Bad).
>>>
>>> Our 2015.01-00231-gab77f24-dirty is 2015.01-00231-gab77f24 + changes
>>> which got merged as 053b86e6d8e50359412e626c33bae3f7bafd74dd in
>>> upstream u-boot.
>>>
>>> Fwiw:
>>> $ git show 2015.01-00231-gab77f24
>>> commit ab77f24119e80257de4ab017b877f92f96980562
>>> Merge: d928664 fa58b10
>>> Author: Tom Rini <trini@ti.com>
>>> Date:   Thu Jan 15 14:05:31 2015 -0500
>>>
>>>     Merge branch 'master' of git://git.denx.de/u-boot-ti
>>>
>>> Which is definately a commit you should hae in your upstream u-boot
>>> tree.
>>
>> Yeah, I suck. I was running:
>>
>>         $ git show gab77f24
>>
>> I didn't know git could parse the full output from git describe.
>>
>>> > I don't have either of those commits in any of the U-Boot trees I
>>> > have.
>>> > Perhaps whatever tree this comes from has local patches that cause
>>> > the
>>> > breakage? The version that I use a recent upstream U-Boot with some
>>> > local patches, none of which should impact Jetson TK1 in any way.
>>> > Just
>>> > to make sure I tried running latest origin/master, which identifies
>>> > thusly:
>>> >
>>> >     U-Boot 2015.10-rc2-00040-g0f9258228e2b
>>> >
>>> > And that boots next-20150818 fine.
>>>
>>> Probably worth for tyler to test that u-boot commit on his jetson to
>>> see if that solves the issue he's having...
>>
>> I've tried reconstructing the version that Tyler is running by checking
>> out 2015.01-00231-gab77f24 and applying 053b86e6d8e5 ("pci: tegra: Fix
>> port information parsing") on top, but that also leaves me with a
>> bootable system, so no way of reproducing. I agree that upgrading to a
>> more recent U-Boot version sounds like the best way forward because it
>> has already proven to work on at least two setups.
>
> Sorry for the delay. I've upgraded u-boot to U-Boot
> 2015.10-rc2-00439-g03d8714 using the tegra u-boot flashing scripts.
> FWIW, I did have to revert 620776d734e4 ("tftp: adjust settings to be
> suitable for 100Mbit ethernet") to get TFTP working again.
>
> Anyways, it hangs at the exact same spot[1] with the newer version of
> u-boot. If remove the modules from the initrd or just disable
> CONFIG_SND_HDA_TEGRA it boots fine. This weekend I'll try to debug
> this module manually and see if I draw any conclusions.

Since there is no movement on this, and jetson hasn't been boot for
multi_v7_defconfig for a while[1], I think it's time to undo the
option causing this problem[2] so that v4.3 will actually boot on the
jetson.

Unless I hear a good reason otherwise, I'll be posting a patch to
disable the HDA related options in multi_v7_defconfig.

Kevin

[1] http://kernelci.org/boot/tegra124-jetson-tk1/?multi_v7_defconfig
[2]

Comments

Jon Hunter Sept. 11, 2015, 10:39 a.m. UTC | #1 
Hi Kevin,

On 10/09/15 22:29, Kevin Hilman wrote:

[snip]

> Since there is no movement on this, and jetson hasn't been boot for
> multi_v7_defconfig for a while[1], I think it's time to undo the
> option causing this problem[2] so that v4.3 will actually boot on the
> jetson.
> 
> Unless I hear a good reason otherwise, I'll be posting a patch to
> disable the HDA related options in multi_v7_defconfig.

So curiosity got the better of this cat, as to why we are not seeing
this ;-)

The main difference I see between the tegra_defconfig and 
multi_v7_defconfig is all the sound drivers are modules (including 
this one).

So trying a quick modprobe of the hda-tegra driver I do see it hang ...

/ # modprobe snd-hda-tegra
[  625.213864] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
[  625.220215] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
[  625.226480] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
[  625.233168] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
[  625.239062] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
[  625.245314] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
[  625.251321] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
[  625.258081] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
[  625.264078] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
[  625.270607] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
[  840.117528] INFO: task modprobe:137 blocked for more than 120 seconds.
[  840.124192]       Not tainted 4.2.0-next-20150909-40826-gb799053 #1
[  840.130584] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  840.138540] modprobe        D c09ac3a4     0   137     82 0x00000000
[  840.145123] [<c09ac3a4>] (__schedule) from [<c09ac838>] (schedule+0x34/0x98)
[  840.152310] [<c09ac838>] (schedule) from [<c09acaac>] (schedule_preempt_disabled+0xc/0x10)
[  840.160734] [<c09acaac>] (schedule_preempt_disabled) from [<c09adeec>] (__mutex_lock_slowpath+0x9c/0x150)
[  840.170458] [<c09adeec>] (__mutex_lock_slowpath) from [<c09adfec>] (mutex_lock+0x4c/0x50)
[  840.178807] [<c09adfec>] (mutex_lock) from [<c062999c>] (__driver_attach+0x44/0x90)
[  840.186627] [<c062999c>] (__driver_attach) from [<c0627fcc>] (bus_for_each_dev+0x54/0x88)
[  840.194966] [<c0627fcc>] (bus_for_each_dev) from [<c0628f88>] (bus_add_driver+0xe4/0x1f0)
[  840.203305] [<c0628f88>] (bus_add_driver) from [<c062a1d0>] (driver_register+0x78/0xf4)
[  840.211475] [<c062a1d0>] (driver_register) from [<c020ac04>] (do_one_initcall+0x80/0x1d0)
[  840.219818] [<c020ac04>] (do_one_initcall) from [<c02c8abc>] (do_init_module+0x58/0x354)
[  840.228081] [<c02c8abc>] (do_init_module) from [<c02afae8>] (load_module+0x17e0/0x1d8c)
[  840.236258] [<c02afae8>] (load_module) from [<c02b016c>] (SyS_init_module+0xd8/0x138)
[  840.244260] [<c02b016c>] (SyS_init_module) from [<c0210b00>] (ret_fast_syscall+0x0/0x3c)

Adding some debug it appears to hang on snd-hda-codec-hdmi  (the following show
the order in which modules are being loaded) ...

/ # modprobe snd-hda-tegra
[   22.450276] snd_hda_tegra: err = -2
[   22.484535] soundcore: err = 0
[   22.488964] snd: err = 0
[   22.493242] snd_timer: err = 0
[   22.498380] snd_pcm: err = 0
[   22.502479] snd_hda_core: err = 0
[   22.508337] snd_hda_codec: err = 0
[   22.513386] snd_hda_tegra: err = 0
[   22.740216] snd_hda_codec_hdmi: err = 0

[hangs here]

However, if I do the following, this works ...

/ # modprobe snd-hda-codec-hdmi
/ # modprobe snd-hda-tegra

So it implies that snd-hda-codec-hdmi needs to be loaded first otherwise it hangs.

Thierry, any thoughts?

Jon
Jon Hunter Sept. 11, 2015, 11:04 a.m. UTC | #2 
On 11/09/15 11:39, Jon Hunter wrote:
> Hi Kevin,
> 
> On 10/09/15 22:29, Kevin Hilman wrote:
> 
> [snip]
> 
>> Since there is no movement on this, and jetson hasn't been boot for
>> multi_v7_defconfig for a while[1], I think it's time to undo the
>> option causing this problem[2] so that v4.3 will actually boot on the
>> jetson.
>>
>> Unless I hear a good reason otherwise, I'll be posting a patch to
>> disable the HDA related options in multi_v7_defconfig.
> 
> So curiosity got the better of this cat, as to why we are not seeing
> this ;-)
> 
> The main difference I see between the tegra_defconfig and 
> multi_v7_defconfig is all the sound drivers are modules (including 
> this one).
> 
> So trying a quick modprobe of the hda-tegra driver I do see it hang ...
> 
> / # modprobe snd-hda-tegra
> [  625.213864] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
> [  625.220215] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
> [  625.226480] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
> [  625.233168] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
> [  625.239062] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
> [  625.245314] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
> [  625.251321] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
> [  625.258081] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
> [  625.264078] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
> [  625.270607] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
> [  840.117528] INFO: task modprobe:137 blocked for more than 120 seconds.
> [  840.124192]       Not tainted 4.2.0-next-20150909-40826-gb799053 #1
> [  840.130584] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [  840.138540] modprobe        D c09ac3a4     0   137     82 0x00000000
> [  840.145123] [<c09ac3a4>] (__schedule) from [<c09ac838>] (schedule+0x34/0x98)
> [  840.152310] [<c09ac838>] (schedule) from [<c09acaac>] (schedule_preempt_disabled+0xc/0x10)
> [  840.160734] [<c09acaac>] (schedule_preempt_disabled) from [<c09adeec>] (__mutex_lock_slowpath+0x9c/0x150)
> [  840.170458] [<c09adeec>] (__mutex_lock_slowpath) from [<c09adfec>] (mutex_lock+0x4c/0x50)
> [  840.178807] [<c09adfec>] (mutex_lock) from [<c062999c>] (__driver_attach+0x44/0x90)
> [  840.186627] [<c062999c>] (__driver_attach) from [<c0627fcc>] (bus_for_each_dev+0x54/0x88)
> [  840.194966] [<c0627fcc>] (bus_for_each_dev) from [<c0628f88>] (bus_add_driver+0xe4/0x1f0)
> [  840.203305] [<c0628f88>] (bus_add_driver) from [<c062a1d0>] (driver_register+0x78/0xf4)
> [  840.211475] [<c062a1d0>] (driver_register) from [<c020ac04>] (do_one_initcall+0x80/0x1d0)
> [  840.219818] [<c020ac04>] (do_one_initcall) from [<c02c8abc>] (do_init_module+0x58/0x354)
> [  840.228081] [<c02c8abc>] (do_init_module) from [<c02afae8>] (load_module+0x17e0/0x1d8c)
> [  840.236258] [<c02afae8>] (load_module) from [<c02b016c>] (SyS_init_module+0xd8/0x138)
> [  840.244260] [<c02b016c>] (SyS_init_module) from [<c0210b00>] (ret_fast_syscall+0x0/0x3c)
> 
> Adding some debug it appears to hang on snd-hda-codec-hdmi  (the following show
> the order in which modules are being loaded) ...
> 
> / # modprobe snd-hda-tegra
> [   22.450276] snd_hda_tegra: err = -2
> [   22.484535] soundcore: err = 0
> [   22.488964] snd: err = 0
> [   22.493242] snd_timer: err = 0
> [   22.498380] snd_pcm: err = 0
> [   22.502479] snd_hda_core: err = 0
> [   22.508337] snd_hda_codec: err = 0
> [   22.513386] snd_hda_tegra: err = 0
> [   22.740216] snd_hda_codec_hdmi: err = 0

Ftrace shows a similar thing ...

/ # cat /debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 8/8   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        modprobe-110   [000] ....    46.095279: module_load: soundcore 
        modprobe-110   [000] .n..    46.096443: module_load: snd 
        modprobe-110   [000] .n..    46.097719: module_load: snd_timer 
        modprobe-110   [000] ....    46.099242: module_load: snd_pcm 
        modprobe-110   [000] ....    46.100231: module_load: snd_hda_core 
        modprobe-110   [000] ....    46.102418: module_load: snd_hda_codec 
        modprobe-110   [000] ....    46.102915: module_load: snd_hda_tegra 
        modprobe-122   [000] ....    46.341224: module_load: snd_hda_codec_hdmi 

However, would imply that snd-hda-codec-hdmi is loaded ok and the hang occurs afterwards
as the trace message is printed once the module has been loaded.

Jon
Thierry Reding Sept. 11, 2015, 12:38 p.m. UTC | #3 
On Fri, Sep 11, 2015 at 11:39:01AM +0100, Jon Hunter wrote:
> Hi Kevin,
> 
> On 10/09/15 22:29, Kevin Hilman wrote:
> 
> [snip]
> 
> > Since there is no movement on this, and jetson hasn't been boot for
> > multi_v7_defconfig for a while[1], I think it's time to undo the
> > option causing this problem[2] so that v4.3 will actually boot on the
> > jetson.
> > 
> > Unless I hear a good reason otherwise, I'll be posting a patch to
> > disable the HDA related options in multi_v7_defconfig.
> 
> So curiosity got the better of this cat, as to why we are not seeing
> this ;-)
> 
> The main difference I see between the tegra_defconfig and 
> multi_v7_defconfig is all the sound drivers are modules (including 
> this one).
> 
> So trying a quick modprobe of the hda-tegra driver I do see it hang ...
> 
> / # modprobe snd-hda-tegra
> [  625.213864] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
> [  625.220215] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
> [  625.226480] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
> [  625.233168] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
> [  625.239062] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
> [  625.245314] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
> [  625.251321] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
> [  625.258081] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
> [  625.264078] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
> [  625.270607] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
> [  840.117528] INFO: task modprobe:137 blocked for more than 120 seconds.
> [  840.124192]       Not tainted 4.2.0-next-20150909-40826-gb799053 #1
> [  840.130584] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [  840.138540] modprobe        D c09ac3a4     0   137     82 0x00000000
> [  840.145123] [<c09ac3a4>] (__schedule) from [<c09ac838>] (schedule+0x34/0x98)
> [  840.152310] [<c09ac838>] (schedule) from [<c09acaac>] (schedule_preempt_disabled+0xc/0x10)
> [  840.160734] [<c09acaac>] (schedule_preempt_disabled) from [<c09adeec>] (__mutex_lock_slowpath+0x9c/0x150)
> [  840.170458] [<c09adeec>] (__mutex_lock_slowpath) from [<c09adfec>] (mutex_lock+0x4c/0x50)
> [  840.178807] [<c09adfec>] (mutex_lock) from [<c062999c>] (__driver_attach+0x44/0x90)
> [  840.186627] [<c062999c>] (__driver_attach) from [<c0627fcc>] (bus_for_each_dev+0x54/0x88)
> [  840.194966] [<c0627fcc>] (bus_for_each_dev) from [<c0628f88>] (bus_add_driver+0xe4/0x1f0)
> [  840.203305] [<c0628f88>] (bus_add_driver) from [<c062a1d0>] (driver_register+0x78/0xf4)
> [  840.211475] [<c062a1d0>] (driver_register) from [<c020ac04>] (do_one_initcall+0x80/0x1d0)
> [  840.219818] [<c020ac04>] (do_one_initcall) from [<c02c8abc>] (do_init_module+0x58/0x354)
> [  840.228081] [<c02c8abc>] (do_init_module) from [<c02afae8>] (load_module+0x17e0/0x1d8c)
> [  840.236258] [<c02afae8>] (load_module) from [<c02b016c>] (SyS_init_module+0xd8/0x138)
> [  840.244260] [<c02b016c>] (SyS_init_module) from [<c0210b00>] (ret_fast_syscall+0x0/0x3c)
> 
> Adding some debug it appears to hang on snd-hda-codec-hdmi  (the following show
> the order in which modules are being loaded) ...
> 
> / # modprobe snd-hda-tegra
> [   22.450276] snd_hda_tegra: err = -2
> [   22.484535] soundcore: err = 0
> [   22.488964] snd: err = 0
> [   22.493242] snd_timer: err = 0
> [   22.498380] snd_pcm: err = 0
> [   22.502479] snd_hda_core: err = 0
> [   22.508337] snd_hda_codec: err = 0
> [   22.513386] snd_hda_tegra: err = 0
> [   22.740216] snd_hda_codec_hdmi: err = 0
> 
> [hangs here]
> 
> However, if I do the following, this works ...
> 
> / # modprobe snd-hda-codec-hdmi
> / # modprobe snd-hda-tegra
> 
> So it implies that snd-hda-codec-hdmi needs to be loaded first otherwise it hangs.
> 
> Thierry, any thoughts?

I can't reproduce this. Booting multi_v7_defconfig on my setup works
just fine. I don't ever see snd-hda-codec-hdmi being probed, but then
probing it manually works fine. No hangs.

What I do see is that after a little while network stops working. I
noticed primarily because I boot with an NFS root, so the kernel started
complaining about the NFS server not responding. Being on an NFS root
could be one reason why this works for me, not sure what the kernelci
labs are running. I don't see the network issues with tegra_defconfig.
I've also tried a tegra_defconfig with all of sound support built as
modules and that all works perfectly.

I'll investigate the multi_v7_defconfig network issues, perhaps that'll
give me some clues, or perhaps even allow me to reproduce the original
issue.

Thierry
Jon Hunter Sept. 11, 2015, 1:10 p.m. UTC | #4 
On 11/09/15 13:38, Thierry Reding wrote:
> * PGP Signed by an unknown key
> 
> On Fri, Sep 11, 2015 at 11:39:01AM +0100, Jon Hunter wrote:
>> Hi Kevin,
>>
>> On 10/09/15 22:29, Kevin Hilman wrote:
>>
>> [snip]
>>
>>> Since there is no movement on this, and jetson hasn't been boot for
>>> multi_v7_defconfig for a while[1], I think it's time to undo the
>>> option causing this problem[2] so that v4.3 will actually boot on the
>>> jetson.
>>>
>>> Unless I hear a good reason otherwise, I'll be posting a patch to
>>> disable the HDA related options in multi_v7_defconfig.
>>
>> So curiosity got the better of this cat, as to why we are not seeing
>> this ;-)
>>
>> The main difference I see between the tegra_defconfig and 
>> multi_v7_defconfig is all the sound drivers are modules (including 
>> this one).
>>
>> So trying a quick modprobe of the hda-tegra driver I do see it hang ...
>>
>> / # modprobe snd-hda-tegra
>> [  625.213864] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
>> [  625.220215] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
>> [  625.226480] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
>> [  625.233168] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
>> [  625.239062] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
>> [  625.245314] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
>> [  625.251321] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
>> [  625.258081] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
>> [  625.264078] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
>> [  625.270607] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
>> [  840.117528] INFO: task modprobe:137 blocked for more than 120 seconds.
>> [  840.124192]       Not tainted 4.2.0-next-20150909-40826-gb799053 #1
>> [  840.130584] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [  840.138540] modprobe        D c09ac3a4     0   137     82 0x00000000
>> [  840.145123] [<c09ac3a4>] (__schedule) from [<c09ac838>] (schedule+0x34/0x98)
>> [  840.152310] [<c09ac838>] (schedule) from [<c09acaac>] (schedule_preempt_disabled+0xc/0x10)
>> [  840.160734] [<c09acaac>] (schedule_preempt_disabled) from [<c09adeec>] (__mutex_lock_slowpath+0x9c/0x150)
>> [  840.170458] [<c09adeec>] (__mutex_lock_slowpath) from [<c09adfec>] (mutex_lock+0x4c/0x50)
>> [  840.178807] [<c09adfec>] (mutex_lock) from [<c062999c>] (__driver_attach+0x44/0x90)
>> [  840.186627] [<c062999c>] (__driver_attach) from [<c0627fcc>] (bus_for_each_dev+0x54/0x88)
>> [  840.194966] [<c0627fcc>] (bus_for_each_dev) from [<c0628f88>] (bus_add_driver+0xe4/0x1f0)
>> [  840.203305] [<c0628f88>] (bus_add_driver) from [<c062a1d0>] (driver_register+0x78/0xf4)
>> [  840.211475] [<c062a1d0>] (driver_register) from [<c020ac04>] (do_one_initcall+0x80/0x1d0)
>> [  840.219818] [<c020ac04>] (do_one_initcall) from [<c02c8abc>] (do_init_module+0x58/0x354)
>> [  840.228081] [<c02c8abc>] (do_init_module) from [<c02afae8>] (load_module+0x17e0/0x1d8c)
>> [  840.236258] [<c02afae8>] (load_module) from [<c02b016c>] (SyS_init_module+0xd8/0x138)
>> [  840.244260] [<c02b016c>] (SyS_init_module) from [<c0210b00>] (ret_fast_syscall+0x0/0x3c)
>>
>> Adding some debug it appears to hang on snd-hda-codec-hdmi  (the following show
>> the order in which modules are being loaded) ...
>>
>> / # modprobe snd-hda-tegra
>> [   22.450276] snd_hda_tegra: err = -2
>> [   22.484535] soundcore: err = 0
>> [   22.488964] snd: err = 0
>> [   22.493242] snd_timer: err = 0
>> [   22.498380] snd_pcm: err = 0
>> [   22.502479] snd_hda_core: err = 0
>> [   22.508337] snd_hda_codec: err = 0
>> [   22.513386] snd_hda_tegra: err = 0
>> [   22.740216] snd_hda_codec_hdmi: err = 0
>>
>> [hangs here]
>>
>> However, if I do the following, this works ...
>>
>> / # modprobe snd-hda-codec-hdmi
>> / # modprobe snd-hda-tegra
>>
>> So it implies that snd-hda-codec-hdmi needs to be loaded first otherwise it hangs.
>>
>> Thierry, any thoughts?
> 
> I can't reproduce this. Booting multi_v7_defconfig on my setup works
> just fine. I don't ever see snd-hda-codec-hdmi being probed, but then
> probing it manually works fine. No hangs.

Did you try "modprobe snd-hda-tegra"? Fails for me 100% of the time.

> What I do see is that after a little while network stops working. I
> noticed primarily because I boot with an NFS root, so the kernel started
> complaining about the NFS server not responding. Being on an NFS root
> could be one reason why this works for me, not sure what the kernelci
> labs are running. I don't see the network issues with tegra_defconfig.
> I've also tried a tegra_defconfig with all of sound support built as
> modules and that all works perfectly.
> 
> I'll investigate the multi_v7_defconfig network issues, perhaps that'll
> give me some clues, or perhaps even allow me to reproduce the original
> issue.

Well I am not using any networking and booting with a simple ramdisk so
I don't think that is the right place to look.

Cheers
Jon
Jon Hunter Sept. 11, 2015, 1:15 p.m. UTC | #5 
On 11/09/15 13:38, Thierry Reding wrote:
> * PGP Signed by an unknown key
> 
> On Fri, Sep 11, 2015 at 11:39:01AM +0100, Jon Hunter wrote:
>> Hi Kevin,
>>
>> On 10/09/15 22:29, Kevin Hilman wrote:
>>
>> [snip]
>>
>>> Since there is no movement on this, and jetson hasn't been boot for
>>> multi_v7_defconfig for a while[1], I think it's time to undo the
>>> option causing this problem[2] so that v4.3 will actually boot on the
>>> jetson.
>>>
>>> Unless I hear a good reason otherwise, I'll be posting a patch to
>>> disable the HDA related options in multi_v7_defconfig.
>>
>> So curiosity got the better of this cat, as to why we are not seeing
>> this ;-)
>>
>> The main difference I see between the tegra_defconfig and 
>> multi_v7_defconfig is all the sound drivers are modules (including 
>> this one).
>>
>> So trying a quick modprobe of the hda-tegra driver I do see it hang ...
>>
>> / # modprobe snd-hda-tegra
>> [  625.213864] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
>> [  625.220215] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
>> [  625.226480] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
>> [  625.233168] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
>> [  625.239062] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
>> [  625.245314] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
>> [  625.251321] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
>> [  625.258081] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
>> [  625.264078] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
>> [  625.270607] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
>> [  840.117528] INFO: task modprobe:137 blocked for more than 120 seconds.
>> [  840.124192]       Not tainted 4.2.0-next-20150909-40826-gb799053 #1
>> [  840.130584] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [  840.138540] modprobe        D c09ac3a4     0   137     82 0x00000000
>> [  840.145123] [<c09ac3a4>] (__schedule) from [<c09ac838>] (schedule+0x34/0x98)
>> [  840.152310] [<c09ac838>] (schedule) from [<c09acaac>] (schedule_preempt_disabled+0xc/0x10)
>> [  840.160734] [<c09acaac>] (schedule_preempt_disabled) from [<c09adeec>] (__mutex_lock_slowpath+0x9c/0x150)
>> [  840.170458] [<c09adeec>] (__mutex_lock_slowpath) from [<c09adfec>] (mutex_lock+0x4c/0x50)
>> [  840.178807] [<c09adfec>] (mutex_lock) from [<c062999c>] (__driver_attach+0x44/0x90)
>> [  840.186627] [<c062999c>] (__driver_attach) from [<c0627fcc>] (bus_for_each_dev+0x54/0x88)
>> [  840.194966] [<c0627fcc>] (bus_for_each_dev) from [<c0628f88>] (bus_add_driver+0xe4/0x1f0)
>> [  840.203305] [<c0628f88>] (bus_add_driver) from [<c062a1d0>] (driver_register+0x78/0xf4)
>> [  840.211475] [<c062a1d0>] (driver_register) from [<c020ac04>] (do_one_initcall+0x80/0x1d0)
>> [  840.219818] [<c020ac04>] (do_one_initcall) from [<c02c8abc>] (do_init_module+0x58/0x354)
>> [  840.228081] [<c02c8abc>] (do_init_module) from [<c02afae8>] (load_module+0x17e0/0x1d8c)
>> [  840.236258] [<c02afae8>] (load_module) from [<c02b016c>] (SyS_init_module+0xd8/0x138)
>> [  840.244260] [<c02b016c>] (SyS_init_module) from [<c0210b00>] (ret_fast_syscall+0x0/0x3c)
>>
>> Adding some debug it appears to hang on snd-hda-codec-hdmi  (the following show
>> the order in which modules are being loaded) ...
>>
>> / # modprobe snd-hda-tegra
>> [   22.450276] snd_hda_tegra: err = -2
>> [   22.484535] soundcore: err = 0
>> [   22.488964] snd: err = 0
>> [   22.493242] snd_timer: err = 0
>> [   22.498380] snd_pcm: err = 0
>> [   22.502479] snd_hda_core: err = 0
>> [   22.508337] snd_hda_codec: err = 0
>> [   22.513386] snd_hda_tegra: err = 0
>> [   22.740216] snd_hda_codec_hdmi: err = 0
>>
>> [hangs here]
>>
>> However, if I do the following, this works ...
>>
>> / # modprobe snd-hda-codec-hdmi
>> / # modprobe snd-hda-tegra
>>
>> So it implies that snd-hda-codec-hdmi needs to be loaded first otherwise it hangs.
>>
>> Thierry, any thoughts?
> 
> I can't reproduce this. Booting multi_v7_defconfig on my setup works
> just fine. I don't ever see snd-hda-codec-hdmi being probed, but then
> probing it manually works fine. No hangs.

To be clear, booting multi_v7_defconfig works just fine for me too and
has been working fine for months. However, the reason I am not seeing
the issue Kevin and Tyler are reporting is because I never attempt to
"modprobe snd-hda-tegra" after boot. If I do then I see a hang. So I
believe the only reason we don't see this is because their setup is
loading modules.

Cheers
Jon
Thierry Reding Sept. 11, 2015, 1:21 p.m. UTC | #6 
On Fri, Sep 11, 2015 at 02:15:00PM +0100, Jon Hunter wrote:
> 
> On 11/09/15 13:38, Thierry Reding wrote:
> > * PGP Signed by an unknown key
> > 
> > On Fri, Sep 11, 2015 at 11:39:01AM +0100, Jon Hunter wrote:
> >> Hi Kevin,
> >>
> >> On 10/09/15 22:29, Kevin Hilman wrote:
> >>
> >> [snip]
> >>
> >>> Since there is no movement on this, and jetson hasn't been boot for
> >>> multi_v7_defconfig for a while[1], I think it's time to undo the
> >>> option causing this problem[2] so that v4.3 will actually boot on the
> >>> jetson.
> >>>
> >>> Unless I hear a good reason otherwise, I'll be posting a patch to
> >>> disable the HDA related options in multi_v7_defconfig.
> >>
> >> So curiosity got the better of this cat, as to why we are not seeing
> >> this ;-)
> >>
> >> The main difference I see between the tegra_defconfig and 
> >> multi_v7_defconfig is all the sound drivers are modules (including 
> >> this one).
> >>
> >> So trying a quick modprobe of the hda-tegra driver I do see it hang ...
> >>
> >> / # modprobe snd-hda-tegra
> >> [  625.213864] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
> >> [  625.220215] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
> >> [  625.226480] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
> >> [  625.233168] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
> >> [  625.239062] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
> >> [  625.245314] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
> >> [  625.251321] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
> >> [  625.258081] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
> >> [  625.264078] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
> >> [  625.270607] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
> >> [  840.117528] INFO: task modprobe:137 blocked for more than 120 seconds.
> >> [  840.124192]       Not tainted 4.2.0-next-20150909-40826-gb799053 #1
> >> [  840.130584] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [  840.138540] modprobe        D c09ac3a4     0   137     82 0x00000000
> >> [  840.145123] [<c09ac3a4>] (__schedule) from [<c09ac838>] (schedule+0x34/0x98)
> >> [  840.152310] [<c09ac838>] (schedule) from [<c09acaac>] (schedule_preempt_disabled+0xc/0x10)
> >> [  840.160734] [<c09acaac>] (schedule_preempt_disabled) from [<c09adeec>] (__mutex_lock_slowpath+0x9c/0x150)
> >> [  840.170458] [<c09adeec>] (__mutex_lock_slowpath) from [<c09adfec>] (mutex_lock+0x4c/0x50)
> >> [  840.178807] [<c09adfec>] (mutex_lock) from [<c062999c>] (__driver_attach+0x44/0x90)
> >> [  840.186627] [<c062999c>] (__driver_attach) from [<c0627fcc>] (bus_for_each_dev+0x54/0x88)
> >> [  840.194966] [<c0627fcc>] (bus_for_each_dev) from [<c0628f88>] (bus_add_driver+0xe4/0x1f0)
> >> [  840.203305] [<c0628f88>] (bus_add_driver) from [<c062a1d0>] (driver_register+0x78/0xf4)
> >> [  840.211475] [<c062a1d0>] (driver_register) from [<c020ac04>] (do_one_initcall+0x80/0x1d0)
> >> [  840.219818] [<c020ac04>] (do_one_initcall) from [<c02c8abc>] (do_init_module+0x58/0x354)
> >> [  840.228081] [<c02c8abc>] (do_init_module) from [<c02afae8>] (load_module+0x17e0/0x1d8c)
> >> [  840.236258] [<c02afae8>] (load_module) from [<c02b016c>] (SyS_init_module+0xd8/0x138)
> >> [  840.244260] [<c02b016c>] (SyS_init_module) from [<c0210b00>] (ret_fast_syscall+0x0/0x3c)
> >>
> >> Adding some debug it appears to hang on snd-hda-codec-hdmi  (the following show
> >> the order in which modules are being loaded) ...
> >>
> >> / # modprobe snd-hda-tegra
> >> [   22.450276] snd_hda_tegra: err = -2
> >> [   22.484535] soundcore: err = 0
> >> [   22.488964] snd: err = 0
> >> [   22.493242] snd_timer: err = 0
> >> [   22.498380] snd_pcm: err = 0
> >> [   22.502479] snd_hda_core: err = 0
> >> [   22.508337] snd_hda_codec: err = 0
> >> [   22.513386] snd_hda_tegra: err = 0
> >> [   22.740216] snd_hda_codec_hdmi: err = 0
> >>
> >> [hangs here]
> >>
> >> However, if I do the following, this works ...
> >>
> >> / # modprobe snd-hda-codec-hdmi
> >> / # modprobe snd-hda-tegra
> >>
> >> So it implies that snd-hda-codec-hdmi needs to be loaded first otherwise it hangs.
> >>
> >> Thierry, any thoughts?
> > 
> > I can't reproduce this. Booting multi_v7_defconfig on my setup works
> > just fine. I don't ever see snd-hda-codec-hdmi being probed, but then
> > probing it manually works fine. No hangs.
> 
> To be clear, booting multi_v7_defconfig works just fine for me too and
> has been working fine for months. However, the reason I am not seeing
> the issue Kevin and Tyler are reporting is because I never attempt to
> "modprobe snd-hda-tegra" after boot. If I do then I see a hang. So I
> believe the only reason we don't see this is because their setup is
> loading modules.

snd-hda-tegra is auto-loaded on boot for me as well and I don't see any
hangs either. I can also unload and reload the module just fine. I've
tested this on next-20150911.

Thierry
Thierry Reding Sept. 11, 2015, 1:25 p.m. UTC | #7 
On Fri, Sep 11, 2015 at 02:10:59PM +0100, Jon Hunter wrote:
> 
> On 11/09/15 13:38, Thierry Reding wrote:
> > * PGP Signed by an unknown key
> > 
> > On Fri, Sep 11, 2015 at 11:39:01AM +0100, Jon Hunter wrote:
> >> Hi Kevin,
> >>
> >> On 10/09/15 22:29, Kevin Hilman wrote:
> >>
> >> [snip]
> >>
> >>> Since there is no movement on this, and jetson hasn't been boot for
> >>> multi_v7_defconfig for a while[1], I think it's time to undo the
> >>> option causing this problem[2] so that v4.3 will actually boot on the
> >>> jetson.
> >>>
> >>> Unless I hear a good reason otherwise, I'll be posting a patch to
> >>> disable the HDA related options in multi_v7_defconfig.
> >>
> >> So curiosity got the better of this cat, as to why we are not seeing
> >> this ;-)
> >>
> >> The main difference I see between the tegra_defconfig and 
> >> multi_v7_defconfig is all the sound drivers are modules (including 
> >> this one).
> >>
> >> So trying a quick modprobe of the hda-tegra driver I do see it hang ...
> >>
> >> / # modprobe snd-hda-tegra
> >> [  625.213864] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
> >> [  625.220215] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
> >> [  625.226480] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
> >> [  625.233168] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
> >> [  625.239062] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
> >> [  625.245314] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
> >> [  625.251321] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
> >> [  625.258081] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
> >> [  625.264078] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
> >> [  625.270607] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
> >> [  840.117528] INFO: task modprobe:137 blocked for more than 120 seconds.
> >> [  840.124192]       Not tainted 4.2.0-next-20150909-40826-gb799053 #1
> >> [  840.130584] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> [  840.138540] modprobe        D c09ac3a4     0   137     82 0x00000000
> >> [  840.145123] [<c09ac3a4>] (__schedule) from [<c09ac838>] (schedule+0x34/0x98)
> >> [  840.152310] [<c09ac838>] (schedule) from [<c09acaac>] (schedule_preempt_disabled+0xc/0x10)
> >> [  840.160734] [<c09acaac>] (schedule_preempt_disabled) from [<c09adeec>] (__mutex_lock_slowpath+0x9c/0x150)
> >> [  840.170458] [<c09adeec>] (__mutex_lock_slowpath) from [<c09adfec>] (mutex_lock+0x4c/0x50)
> >> [  840.178807] [<c09adfec>] (mutex_lock) from [<c062999c>] (__driver_attach+0x44/0x90)
> >> [  840.186627] [<c062999c>] (__driver_attach) from [<c0627fcc>] (bus_for_each_dev+0x54/0x88)
> >> [  840.194966] [<c0627fcc>] (bus_for_each_dev) from [<c0628f88>] (bus_add_driver+0xe4/0x1f0)
> >> [  840.203305] [<c0628f88>] (bus_add_driver) from [<c062a1d0>] (driver_register+0x78/0xf4)
> >> [  840.211475] [<c062a1d0>] (driver_register) from [<c020ac04>] (do_one_initcall+0x80/0x1d0)
> >> [  840.219818] [<c020ac04>] (do_one_initcall) from [<c02c8abc>] (do_init_module+0x58/0x354)
> >> [  840.228081] [<c02c8abc>] (do_init_module) from [<c02afae8>] (load_module+0x17e0/0x1d8c)
> >> [  840.236258] [<c02afae8>] (load_module) from [<c02b016c>] (SyS_init_module+0xd8/0x138)
> >> [  840.244260] [<c02b016c>] (SyS_init_module) from [<c0210b00>] (ret_fast_syscall+0x0/0x3c)
> >>
> >> Adding some debug it appears to hang on snd-hda-codec-hdmi  (the following show
> >> the order in which modules are being loaded) ...
> >>
> >> / # modprobe snd-hda-tegra
> >> [   22.450276] snd_hda_tegra: err = -2
> >> [   22.484535] soundcore: err = 0
> >> [   22.488964] snd: err = 0
> >> [   22.493242] snd_timer: err = 0
> >> [   22.498380] snd_pcm: err = 0
> >> [   22.502479] snd_hda_core: err = 0
> >> [   22.508337] snd_hda_codec: err = 0
> >> [   22.513386] snd_hda_tegra: err = 0
> >> [   22.740216] snd_hda_codec_hdmi: err = 0
> >>
> >> [hangs here]
> >>
> >> However, if I do the following, this works ...
> >>
> >> / # modprobe snd-hda-codec-hdmi
> >> / # modprobe snd-hda-tegra
> >>
> >> So it implies that snd-hda-codec-hdmi needs to be loaded first otherwise it hangs.
> >>
> >> Thierry, any thoughts?
> > 
> > I can't reproduce this. Booting multi_v7_defconfig on my setup works
> > just fine. I don't ever see snd-hda-codec-hdmi being probed, but then
> > probing it manually works fine. No hangs.
> 
> Did you try "modprobe snd-hda-tegra"? Fails for me 100% of the time.

Works for me 100% of the time. Unloading and reloading isn't a problem
either. What revision of the Jetson TK1 do you have? Mine is a C.2

> > What I do see is that after a little while network stops working. I
> > noticed primarily because I boot with an NFS root, so the kernel started
> > complaining about the NFS server not responding. Being on an NFS root
> > could be one reason why this works for me, not sure what the kernelci
> > labs are running. I don't see the network issues with tegra_defconfig.
> > I've also tried a tegra_defconfig with all of sound support built as
> > modules and that all works perfectly.
> > 
> > I'll investigate the multi_v7_defconfig network issues, perhaps that'll
> > give me some clues, or perhaps even allow me to reproduce the original
> > issue.
> 
> Well I am not using any networking and booting with a simple ramdisk so
> I don't think that is the right place to look.

Looks like this might have been a transient issue with my networking
setup. I can no longer reproduce the NFS hangs.

What sort of ramdisk do you use? Can you share the instructions you use
to create it? Perhaps I can reproduce that way.

Thierry
Jon Hunter Sept. 11, 2015, 1:39 p.m. UTC | #8 
On 11/09/15 14:21, Thierry Reding wrote:
> * PGP Signed by an unknown key
> 
> On Fri, Sep 11, 2015 at 02:15:00PM +0100, Jon Hunter wrote:
>>
>> On 11/09/15 13:38, Thierry Reding wrote:
>>>> Old Signed by an unknown key
>>>
>>> On Fri, Sep 11, 2015 at 11:39:01AM +0100, Jon Hunter wrote:
>>>> Hi Kevin,
>>>>
>>>> On 10/09/15 22:29, Kevin Hilman wrote:
>>>>
>>>> [snip]
>>>>
>>>>> Since there is no movement on this, and jetson hasn't been boot for
>>>>> multi_v7_defconfig for a while[1], I think it's time to undo the
>>>>> option causing this problem[2] so that v4.3 will actually boot on the
>>>>> jetson.
>>>>>
>>>>> Unless I hear a good reason otherwise, I'll be posting a patch to
>>>>> disable the HDA related options in multi_v7_defconfig.
>>>>
>>>> So curiosity got the better of this cat, as to why we are not seeing
>>>> this ;-)
>>>>
>>>> The main difference I see between the tegra_defconfig and 
>>>> multi_v7_defconfig is all the sound drivers are modules (including 
>>>> this one).
>>>>
>>>> So trying a quick modprobe of the hda-tegra driver I do see it hang ...
>>>>
>>>> / # modprobe snd-hda-tegra
>>>> [  625.213864] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
>>>> [  625.220215] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
>>>> [  625.226480] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
>>>> [  625.233168] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
>>>> [  625.239062] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
>>>> [  625.245314] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
>>>> [  625.251321] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
>>>> [  625.258081] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
>>>> [  625.264078] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
>>>> [  625.270607] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
>>>> [  840.117528] INFO: task modprobe:137 blocked for more than 120 seconds.
>>>> [  840.124192]       Not tainted 4.2.0-next-20150909-40826-gb799053 #1
>>>> [  840.130584] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>>> [  840.138540] modprobe        D c09ac3a4     0   137     82 0x00000000
>>>> [  840.145123] [<c09ac3a4>] (__schedule) from [<c09ac838>] (schedule+0x34/0x98)
>>>> [  840.152310] [<c09ac838>] (schedule) from [<c09acaac>] (schedule_preempt_disabled+0xc/0x10)
>>>> [  840.160734] [<c09acaac>] (schedule_preempt_disabled) from [<c09adeec>] (__mutex_lock_slowpath+0x9c/0x150)
>>>> [  840.170458] [<c09adeec>] (__mutex_lock_slowpath) from [<c09adfec>] (mutex_lock+0x4c/0x50)
>>>> [  840.178807] [<c09adfec>] (mutex_lock) from [<c062999c>] (__driver_attach+0x44/0x90)
>>>> [  840.186627] [<c062999c>] (__driver_attach) from [<c0627fcc>] (bus_for_each_dev+0x54/0x88)
>>>> [  840.194966] [<c0627fcc>] (bus_for_each_dev) from [<c0628f88>] (bus_add_driver+0xe4/0x1f0)
>>>> [  840.203305] [<c0628f88>] (bus_add_driver) from [<c062a1d0>] (driver_register+0x78/0xf4)
>>>> [  840.211475] [<c062a1d0>] (driver_register) from [<c020ac04>] (do_one_initcall+0x80/0x1d0)
>>>> [  840.219818] [<c020ac04>] (do_one_initcall) from [<c02c8abc>] (do_init_module+0x58/0x354)
>>>> [  840.228081] [<c02c8abc>] (do_init_module) from [<c02afae8>] (load_module+0x17e0/0x1d8c)
>>>> [  840.236258] [<c02afae8>] (load_module) from [<c02b016c>] (SyS_init_module+0xd8/0x138)
>>>> [  840.244260] [<c02b016c>] (SyS_init_module) from [<c0210b00>] (ret_fast_syscall+0x0/0x3c)
>>>>
>>>> Adding some debug it appears to hang on snd-hda-codec-hdmi  (the following show
>>>> the order in which modules are being loaded) ...
>>>>
>>>> / # modprobe snd-hda-tegra
>>>> [   22.450276] snd_hda_tegra: err = -2
>>>> [   22.484535] soundcore: err = 0
>>>> [   22.488964] snd: err = 0
>>>> [   22.493242] snd_timer: err = 0
>>>> [   22.498380] snd_pcm: err = 0
>>>> [   22.502479] snd_hda_core: err = 0
>>>> [   22.508337] snd_hda_codec: err = 0
>>>> [   22.513386] snd_hda_tegra: err = 0
>>>> [   22.740216] snd_hda_codec_hdmi: err = 0
>>>>
>>>> [hangs here]
>>>>
>>>> However, if I do the following, this works ...
>>>>
>>>> / # modprobe snd-hda-codec-hdmi
>>>> / # modprobe snd-hda-tegra
>>>>
>>>> So it implies that snd-hda-codec-hdmi needs to be loaded first otherwise it hangs.
>>>>
>>>> Thierry, any thoughts?
>>>
>>> I can't reproduce this. Booting multi_v7_defconfig on my setup works
>>> just fine. I don't ever see snd-hda-codec-hdmi being probed, but then
>>> probing it manually works fine. No hangs.
>>
>> To be clear, booting multi_v7_defconfig works just fine for me too and
>> has been working fine for months. However, the reason I am not seeing
>> the issue Kevin and Tyler are reporting is because I never attempt to
>> "modprobe snd-hda-tegra" after boot. If I do then I see a hang. So I
>> believe the only reason we don't see this is because their setup is
>> loading modules.
> 
> snd-hda-tegra is auto-loaded on boot for me as well and I don't see any
> hangs either. I can also unload and reload the module just fine. I've
> tested this on next-20150911.

What else are you auto-loading? For my testing there appears to be a
sensitivity to order outside of the depmod order.

Can you try unloading all the sound modules and then do a "modprobe
snd-hda-tegra"?

Cheers
Jon
Jon Hunter Sept. 11, 2015, 1:43 p.m. UTC | #9 
On 11/09/15 14:25, Thierry Reding wrote:
> * PGP Signed by an unknown key
> 
> On Fri, Sep 11, 2015 at 02:10:59PM +0100, Jon Hunter wrote:
>>
>> On 11/09/15 13:38, Thierry Reding wrote:
>>>> Old Signed by an unknown key
>>>
>>> On Fri, Sep 11, 2015 at 11:39:01AM +0100, Jon Hunter wrote:
>>>> Hi Kevin,
>>>>
>>>> On 10/09/15 22:29, Kevin Hilman wrote:
>>>>
>>>> [snip]
>>>>
>>>>> Since there is no movement on this, and jetson hasn't been boot for
>>>>> multi_v7_defconfig for a while[1], I think it's time to undo the
>>>>> option causing this problem[2] so that v4.3 will actually boot on the
>>>>> jetson.
>>>>>
>>>>> Unless I hear a good reason otherwise, I'll be posting a patch to
>>>>> disable the HDA related options in multi_v7_defconfig.
>>>>
>>>> So curiosity got the better of this cat, as to why we are not seeing
>>>> this ;-)
>>>>
>>>> The main difference I see between the tegra_defconfig and 
>>>> multi_v7_defconfig is all the sound drivers are modules (including 
>>>> this one).
>>>>
>>>> So trying a quick modprobe of the hda-tegra driver I do see it hang ...
>>>>
>>>> / # modprobe snd-hda-tegra
>>>> [  625.213864] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
>>>> [  625.220215] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
>>>> [  625.226480] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
>>>> [  625.233168] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
>>>> [  625.239062] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
>>>> [  625.245314] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
>>>> [  625.251321] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
>>>> [  625.258081] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
>>>> [  625.264078] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
>>>> [  625.270607] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
>>>> [  840.117528] INFO: task modprobe:137 blocked for more than 120 seconds.
>>>> [  840.124192]       Not tainted 4.2.0-next-20150909-40826-gb799053 #1
>>>> [  840.130584] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>>> [  840.138540] modprobe        D c09ac3a4     0   137     82 0x00000000
>>>> [  840.145123] [<c09ac3a4>] (__schedule) from [<c09ac838>] (schedule+0x34/0x98)
>>>> [  840.152310] [<c09ac838>] (schedule) from [<c09acaac>] (schedule_preempt_disabled+0xc/0x10)
>>>> [  840.160734] [<c09acaac>] (schedule_preempt_disabled) from [<c09adeec>] (__mutex_lock_slowpath+0x9c/0x150)
>>>> [  840.170458] [<c09adeec>] (__mutex_lock_slowpath) from [<c09adfec>] (mutex_lock+0x4c/0x50)
>>>> [  840.178807] [<c09adfec>] (mutex_lock) from [<c062999c>] (__driver_attach+0x44/0x90)
>>>> [  840.186627] [<c062999c>] (__driver_attach) from [<c0627fcc>] (bus_for_each_dev+0x54/0x88)
>>>> [  840.194966] [<c0627fcc>] (bus_for_each_dev) from [<c0628f88>] (bus_add_driver+0xe4/0x1f0)
>>>> [  840.203305] [<c0628f88>] (bus_add_driver) from [<c062a1d0>] (driver_register+0x78/0xf4)
>>>> [  840.211475] [<c062a1d0>] (driver_register) from [<c020ac04>] (do_one_initcall+0x80/0x1d0)
>>>> [  840.219818] [<c020ac04>] (do_one_initcall) from [<c02c8abc>] (do_init_module+0x58/0x354)
>>>> [  840.228081] [<c02c8abc>] (do_init_module) from [<c02afae8>] (load_module+0x17e0/0x1d8c)
>>>> [  840.236258] [<c02afae8>] (load_module) from [<c02b016c>] (SyS_init_module+0xd8/0x138)
>>>> [  840.244260] [<c02b016c>] (SyS_init_module) from [<c0210b00>] (ret_fast_syscall+0x0/0x3c)
>>>>
>>>> Adding some debug it appears to hang on snd-hda-codec-hdmi  (the following show
>>>> the order in which modules are being loaded) ...
>>>>
>>>> / # modprobe snd-hda-tegra
>>>> [   22.450276] snd_hda_tegra: err = -2
>>>> [   22.484535] soundcore: err = 0
>>>> [   22.488964] snd: err = 0
>>>> [   22.493242] snd_timer: err = 0
>>>> [   22.498380] snd_pcm: err = 0
>>>> [   22.502479] snd_hda_core: err = 0
>>>> [   22.508337] snd_hda_codec: err = 0
>>>> [   22.513386] snd_hda_tegra: err = 0
>>>> [   22.740216] snd_hda_codec_hdmi: err = 0
>>>>
>>>> [hangs here]
>>>>
>>>> However, if I do the following, this works ...
>>>>
>>>> / # modprobe snd-hda-codec-hdmi
>>>> / # modprobe snd-hda-tegra
>>>>
>>>> So it implies that snd-hda-codec-hdmi needs to be loaded first otherwise it hangs.
>>>>
>>>> Thierry, any thoughts?
>>>
>>> I can't reproduce this. Booting multi_v7_defconfig on my setup works
>>> just fine. I don't ever see snd-hda-codec-hdmi being probed, but then
>>> probing it manually works fine. No hangs.
>>
>> Did you try "modprobe snd-hda-tegra"? Fails for me 100% of the time.
> 
> Works for me 100% of the time. Unloading and reloading isn't a problem
> either. What revision of the Jetson TK1 do you have? Mine is a C.2
> 
>>> What I do see is that after a little while network stops working. I
>>> noticed primarily because I boot with an NFS root, so the kernel started
>>> complaining about the NFS server not responding. Being on an NFS root
>>> could be one reason why this works for me, not sure what the kernelci
>>> labs are running. I don't see the network issues with tegra_defconfig.
>>> I've also tried a tegra_defconfig with all of sound support built as
>>> modules and that all works perfectly.
>>>
>>> I'll investigate the multi_v7_defconfig network issues, perhaps that'll
>>> give me some clues, or perhaps even allow me to reproduce the original
>>> issue.
>>
>> Well I am not using any networking and booting with a simple ramdisk so
>> I don't think that is the right place to look.
> 
> Looks like this might have been a transient issue with my networking
> setup. I can no longer reproduce the NFS hangs.
> 
> What sort of ramdisk do you use? Can you share the instructions you use
> to create it? Perhaps I can reproduce that way.

It is just a simple busybox based file-system. I can share it with you.

Cheers
Jon
Thierry Reding Sept. 11, 2015, 1:57 p.m. UTC | #10 
On Fri, Sep 11, 2015 at 02:39:33PM +0100, Jon Hunter wrote:
> 
> On 11/09/15 14:21, Thierry Reding wrote:
> > * PGP Signed by an unknown key
> > 
> > On Fri, Sep 11, 2015 at 02:15:00PM +0100, Jon Hunter wrote:
> >>
> >> On 11/09/15 13:38, Thierry Reding wrote:
> >>>> Old Signed by an unknown key
> >>>
> >>> On Fri, Sep 11, 2015 at 11:39:01AM +0100, Jon Hunter wrote:
> >>>> Hi Kevin,
> >>>>
> >>>> On 10/09/15 22:29, Kevin Hilman wrote:
> >>>>
> >>>> [snip]
> >>>>
> >>>>> Since there is no movement on this, and jetson hasn't been boot for
> >>>>> multi_v7_defconfig for a while[1], I think it's time to undo the
> >>>>> option causing this problem[2] so that v4.3 will actually boot on the
> >>>>> jetson.
> >>>>>
> >>>>> Unless I hear a good reason otherwise, I'll be posting a patch to
> >>>>> disable the HDA related options in multi_v7_defconfig.
> >>>>
> >>>> So curiosity got the better of this cat, as to why we are not seeing
> >>>> this ;-)
> >>>>
> >>>> The main difference I see between the tegra_defconfig and 
> >>>> multi_v7_defconfig is all the sound drivers are modules (including 
> >>>> this one).
> >>>>
> >>>> So trying a quick modprobe of the hda-tegra driver I do see it hang ...
> >>>>
> >>>> / # modprobe snd-hda-tegra
> >>>> [  625.213864] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
> >>>> [  625.220215] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
> >>>> [  625.226480] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
> >>>> [  625.233168] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
> >>>> [  625.239062] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
> >>>> [  625.245314] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
> >>>> [  625.251321] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
> >>>> [  625.258081] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
> >>>> [  625.264078] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
> >>>> [  625.270607] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
> >>>> [  840.117528] INFO: task modprobe:137 blocked for more than 120 seconds.
> >>>> [  840.124192]       Not tainted 4.2.0-next-20150909-40826-gb799053 #1
> >>>> [  840.130584] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >>>> [  840.138540] modprobe        D c09ac3a4     0   137     82 0x00000000
> >>>> [  840.145123] [<c09ac3a4>] (__schedule) from [<c09ac838>] (schedule+0x34/0x98)
> >>>> [  840.152310] [<c09ac838>] (schedule) from [<c09acaac>] (schedule_preempt_disabled+0xc/0x10)
> >>>> [  840.160734] [<c09acaac>] (schedule_preempt_disabled) from [<c09adeec>] (__mutex_lock_slowpath+0x9c/0x150)
> >>>> [  840.170458] [<c09adeec>] (__mutex_lock_slowpath) from [<c09adfec>] (mutex_lock+0x4c/0x50)
> >>>> [  840.178807] [<c09adfec>] (mutex_lock) from [<c062999c>] (__driver_attach+0x44/0x90)
> >>>> [  840.186627] [<c062999c>] (__driver_attach) from [<c0627fcc>] (bus_for_each_dev+0x54/0x88)
> >>>> [  840.194966] [<c0627fcc>] (bus_for_each_dev) from [<c0628f88>] (bus_add_driver+0xe4/0x1f0)
> >>>> [  840.203305] [<c0628f88>] (bus_add_driver) from [<c062a1d0>] (driver_register+0x78/0xf4)
> >>>> [  840.211475] [<c062a1d0>] (driver_register) from [<c020ac04>] (do_one_initcall+0x80/0x1d0)
> >>>> [  840.219818] [<c020ac04>] (do_one_initcall) from [<c02c8abc>] (do_init_module+0x58/0x354)
> >>>> [  840.228081] [<c02c8abc>] (do_init_module) from [<c02afae8>] (load_module+0x17e0/0x1d8c)
> >>>> [  840.236258] [<c02afae8>] (load_module) from [<c02b016c>] (SyS_init_module+0xd8/0x138)
> >>>> [  840.244260] [<c02b016c>] (SyS_init_module) from [<c0210b00>] (ret_fast_syscall+0x0/0x3c)
> >>>>
> >>>> Adding some debug it appears to hang on snd-hda-codec-hdmi  (the following show
> >>>> the order in which modules are being loaded) ...
> >>>>
> >>>> / # modprobe snd-hda-tegra
> >>>> [   22.450276] snd_hda_tegra: err = -2
> >>>> [   22.484535] soundcore: err = 0
> >>>> [   22.488964] snd: err = 0
> >>>> [   22.493242] snd_timer: err = 0
> >>>> [   22.498380] snd_pcm: err = 0
> >>>> [   22.502479] snd_hda_core: err = 0
> >>>> [   22.508337] snd_hda_codec: err = 0
> >>>> [   22.513386] snd_hda_tegra: err = 0
> >>>> [   22.740216] snd_hda_codec_hdmi: err = 0
> >>>>
> >>>> [hangs here]
> >>>>
> >>>> However, if I do the following, this works ...
> >>>>
> >>>> / # modprobe snd-hda-codec-hdmi
> >>>> / # modprobe snd-hda-tegra
> >>>>
> >>>> So it implies that snd-hda-codec-hdmi needs to be loaded first otherwise it hangs.
> >>>>
> >>>> Thierry, any thoughts?
> >>>
> >>> I can't reproduce this. Booting multi_v7_defconfig on my setup works
> >>> just fine. I don't ever see snd-hda-codec-hdmi being probed, but then
> >>> probing it manually works fine. No hangs.
> >>
> >> To be clear, booting multi_v7_defconfig works just fine for me too and
> >> has been working fine for months. However, the reason I am not seeing
> >> the issue Kevin and Tyler are reporting is because I never attempt to
> >> "modprobe snd-hda-tegra" after boot. If I do then I see a hang. So I
> >> believe the only reason we don't see this is because their setup is
> >> loading modules.
> > 
> > snd-hda-tegra is auto-loaded on boot for me as well and I don't see any
> > hangs either. I can also unload and reload the module just fine. I've
> > tested this on next-20150911.
> 
> What else are you auto-loading? For my testing there appears to be a
> sensitivity to order outside of the depmod order.
> 
> Can you try unloading all the sound modules and then do a "modprobe
> snd-hda-tegra"?

Here's the list of loaded modules right after boot:

	-sh-4.3# lsmod
	Module                  Size  Used by
	snd_hda_tegra           4764  0 
	snd_hda_codec_hdmi     35010  1 
	snd_soc_tegra30_i2s     5380  2 
	snd_soc_tegra_pcm       1184  1 snd_soc_tegra30_i2s
	snd_soc_tegra_rt5640     3960  0 
	snd_soc_rt5640         56972  1 
	snd_soc_tegra_utils     2825  1 snd_soc_tegra_rt5640
	snd_soc_rl6231          1897  1 snd_soc_rt5640
	snd_soc_core          107271  4
	snd_soc_tegra_pcm,snd_soc_rt5640,snd_soc_tegra_rt5640,snd_soc_tegra30_i2s
	snd_hda_codec          75955  2 snd_hda_codec_hdmi,snd_hda_tegra
	snd_compress            7363  1 snd_soc_core
	snd_hda_core           26603  3
	snd_hda_codec_hdmi,snd_hda_codec,snd_hda_tegra
	snd_pcm_dmaengine       2943  1 snd_soc_core
	snd_pcm                69108  7
	snd_soc_rt5640,snd_soc_core,snd_hda_codec_hdmi,snd_hda_codec,snd_hda_tegra,snd_pcm_dmaengine,snd_hda_core
	snd_timer              17264  1 snd_pcm
	snd_soc_tegra30_ahub     8299  1 snd_soc_tegra30_i2s
	snd                    42248  7
	snd_soc_core,snd_timer,snd_hda_codec_hdmi,snd_pcm,snd_hda_codec,snd_hda_tegra,snd_compress
	nouveau              1302185  0 
	soundcore                858  1 snd
	tegra_devfreq           5375  0 
	ttm                    65238  1 nouveau

Then I went and unloaded a couple of modules until I was left with this:

	-sh-4.3# lsmod
	Module                  Size  Used by
	nouveau              1302185  0 
	tegra_devfreq           5375  0 
	ttm                    65238  1 nouveau

Then I did the following:

	-sh-4.3# modprobe snd-hda-tegra
	[ 2243.786143] hdaudio hdaudioC0D3: Unable to bind the codec
	-sh-4.3# lsmod
	Module                  Size  Used by
	snd_hda_tegra           4764  0 
	snd_hda_codec          75955  1 snd_hda_tegra
	snd_hda_core           26603  2 snd_hda_codec,snd_hda_tegra
	snd_pcm                69108  3 snd_hda_codec,snd_hda_tegra,snd_hda_core
	snd_timer              17264  1 snd_pcm
	snd                    42248  4 snd_timer,snd_pcm,snd_hda_codec,snd_hda_tegra
	soundcore                858  1 snd
	nouveau              1302185  0 
	tegra_devfreq           5375  0 
	ttm                    65238  1 nouveau
	-sh-4.3# modprobe snd-hda-codec-hdmi
	-sh-4.3# modprobe -r snd-hda-tegra
	-sh-4.3# modprobe snd-hda-tegra
	[ 2263.934328] input: tegra-hda HDMI/DP,pcm=3 as /devices/soc0/70030000.hda/sound/card0/input4

So all worked just fine.

Thierry
Jon Hunter Sept. 11, 2015, 2:08 p.m. UTC | #11 
On 11/09/15 14:57, Thierry Reding wrote:

[snip]

> Then I did the following:
> 
> 	-sh-4.3# modprobe snd-hda-tegra
> 	[ 2243.786143] hdaudio hdaudioC0D3: Unable to bind the codec
> 	-sh-4.3# lsmod
> 	Module                  Size  Used by
> 	snd_hda_tegra           4764  0 
> 	snd_hda_codec          75955  1 snd_hda_tegra
> 	snd_hda_core           26603  2 snd_hda_codec,snd_hda_tegra
> 	snd_pcm                69108  3 snd_hda_codec,snd_hda_tegra,snd_hda_core
> 	snd_timer              17264  1 snd_pcm
> 	snd                    42248  4 snd_timer,snd_pcm,snd_hda_codec,snd_hda_tegra
> 	soundcore                858  1 snd
> 	nouveau              1302185  0 
> 	tegra_devfreq           5375  0 
> 	ttm                    65238  1 nouveau
> 	-sh-4.3# modprobe snd-hda-codec-hdmi
> 	-sh-4.3# modprobe -r snd-hda-tegra
> 	-sh-4.3# modprobe snd-hda-tegra
> 	[ 2263.934328] input: tegra-hda HDMI/DP,pcm=3 as /devices/soc0/70030000.hda/sound/card0/input4
> 
> So all worked just fine.

That's interesting. For me (as per my earlier email), I did not see the
"unable to bind the codec" and modprobe attempted to load
snd-hda-codec-hdmi after snd-hda-tega. Puzzled.

Jon
Jon Hunter Sept. 11, 2015, 3:51 p.m. UTC | #12 
On 11/09/15 14:25, Thierry Reding wrote:

[snip]

> Works for me 100% of the time. Unloading and reloading isn't a problem
> either. What revision of the Jetson TK1 do you have? Mine is a C.2

Unfortunately, I am not sure it is whatever is in Paul's automation rig
[0]. However, I have also reproduced this on a tegra124 nyan-big in the
office.

Cheers
Jon

[0] http://nvtb.github.io/linux-next/
Thierry Reding Sept. 11, 2015, 3:59 p.m. UTC | #13 
On Fri, Sep 11, 2015 at 04:51:49PM +0100, Jon Hunter wrote:
> 
> On 11/09/15 14:25, Thierry Reding wrote:
> 
> [snip]
> 
> > Works for me 100% of the time. Unloading and reloading isn't a problem
> > either. What revision of the Jetson TK1 do you have? Mine is a C.2
> 
> Unfortunately, I am not sure it is whatever is in Paul's automation rig
> [0]. However, I have also reproduced this on a tegra124 nyan-big in the
> office.

I was able to reproduce this using a busybox initial ramdisk. Just to
make sure I built a separate one from git and it exposes the same
behaviour. I suspect that this is some sort of weird interaction between
mdev and async probing and nobody's noticed so far because async probing
isn't very common (at least in the ARM world).

I'll be off for the weekend soonish, but I'll try to find some more time
next week to track this down.

Thierry
Thierry Reding Sept. 11, 2015, 4:33 p.m. UTC | #14 
On Fri, Sep 11, 2015 at 05:59:48PM +0200, Thierry Reding wrote:
> On Fri, Sep 11, 2015 at 04:51:49PM +0100, Jon Hunter wrote:
> > 
> > On 11/09/15 14:25, Thierry Reding wrote:
> > 
> > [snip]
> > 
> > > Works for me 100% of the time. Unloading and reloading isn't a problem
> > > either. What revision of the Jetson TK1 do you have? Mine is a C.2
> > 
> > Unfortunately, I am not sure it is whatever is in Paul's automation rig
> > [0]. However, I have also reproduced this on a tegra124 nyan-big in the
> > office.
> 
> I was able to reproduce this using a busybox initial ramdisk. Just to
> make sure I built a separate one from git and it exposes the same
> behaviour. I suspect that this is some sort of weird interaction between
> mdev and async probing and nobody's noticed so far because async probing
> isn't very common (at least in the ARM world).
> 
> I'll be off for the weekend soonish, but I'll try to find some more time
> next week to track this down.

Before I head into the weekend, here are my findings: looks like this
might be some sort of recursive locking problem. Here's the output with
a lot of debug messages:

	/ # modprobe snd-hda-tegra
	[  298.765514] snd_hda_tegra: Unknown symbol snd_hdac_bus_enter_link_reset (err 0)
	[  298.773024] snd_hda_tegra: Unknown symbol azx_probe_codecs (err 0)
	[  298.779332] snd_hda_tegra: Unknown symbol snd_card_register (err 0)
	[  298.785834] snd_hda_tegra: Unknown symbol snd_card_free (err 0)
	[  298.792015] snd_hda_tegra: Unknown symbol azx_init_streams (err 0)
	[  298.798485] snd_hda_tegra: Unknown symbol azx_stop_all_streams (err 0)
	[  298.805234] snd_hda_tegra: Unknown symbol snd_dma_free_pages (err 0)
	[  298.811816] snd_hda_tegra: Unknown symbol snd_hdac_bus_free_stream_pages (err 0)
	[  298.819413] snd_hda_tegra: Unknown symbol snd_hdac_bus_exit (err 0)
	[  298.825919] snd_hda_tegra: Unknown symbol snd_card_new (err 0)
	[  298.832003] snd_hda_tegra: Unknown symbol snd_pcm_lib_malloc_pages (err 0)
	[  298.839080] snd_hda_tegra: Unknown symbol snd_pcm_lib_free_pages (err 0)
	[  298.846033] snd_hda_tegra: Unknown symbol azx_bus_init (err 0)
	[  298.852070] snd_hda_tegra: Unknown symbol azx_free_streams (err 0)
	[  298.858475] snd_hda_tegra: Unknown symbol azx_init_chip (err 0)
	[  298.864626] snd_hda_tegra: Unknown symbol snd_device_new (err 0)
	[  298.870856] snd_hda_tegra: Unknown symbol snd_hda_set_power_save (err 0)
	[  298.877802] snd_hda_tegra: Unknown symbol azx_stop_chip (err 0)
	[  298.883953] snd_hda_tegra: Unknown symbol azx_codec_configure (err 0)
	[  298.890598] snd_hda_tegra: Unknown symbol snd_dma_alloc_pages (err 0)
	[  298.897274] snd_hda_tegra: Unknown symbol snd_hdac_bus_alloc_stream_pages (err 0)
	[  298.904975] snd_hda_tegra: Unknown symbol azx_interrupt (err 0)
	[  299.024167] device: 'timer': device_add
	[  299.031120] > driver_register(drv=bf06dd24)
	[  299.035294]   finding driver...
	[  299.038495]   adding driver...
	[  299.041605] > __driver_attach(dev=ed805810, data=bf06dd24)
	[  299.047115]   matching device...
	[  299.050352] > __driver_attach(dev=ed983e10, data=bf06dd24)
	[  299.055857]   matching device...
	[  299.059086] > __driver_attach(dev=ed9a2010, data=bf06dd24)
	[  299.064606]   matching device...
	[  299.067872] > __driver_attach(dev=ed9a2210, data=bf06dd24)
	[  299.073384]   matching device...
	[  299.076658] > __driver_attach(dev=ed9a2410, data=bf06dd24)
	[  299.082171]   matching device...
	[  299.085408] > __driver_attach(dev=ed9a2610, data=bf06dd24)
	[  299.090912]   matching device...
	[  299.094141] > __driver_attach(dev=ed9a2810, data=bf06dd24)
	[  299.099655]   matching device...
	[  299.102924] > __driver_attach(dev=ed9a2a10, data=bf06dd24)
	[  299.108435]   matching device...
	[  299.111710] > __driver_attach(dev=ed9a2c10, data=bf06dd24)
	[  299.117221]   matching device...
	[  299.120459] > __driver_attach(dev=ed9a2e10, data=bf06dd24)
	[  299.125963]   matching device...
	[  299.129192] > __driver_attach(dev=ed9a3010, data=bf06dd24)
	[  299.134706]   matching device...
	[  299.137976] > __driver_attach(dev=ed9a3210, data=bf06dd24)
	[  299.143487]   matching device...
	[  299.146762] > __driver_attach(dev=ed9a3410, data=bf06dd24)
	[  299.152273]   matching device...
	[  299.155511] > __driver_attach(dev=ed9a3610, data=bf06dd24)
	[  299.161015]   matching device...
	[  299.164253] > __driver_attach(dev=ed9a3810, data=bf06dd24)
	[  299.169752]   matching device...
	[  299.173016] > __driver_attach(dev=ed9a3a10, data=bf06dd24)
	[  299.178527]   matching device...
	[  299.181802] > __driver_attach(dev=ed9a3c10, data=bf06dd24)
	[  299.187325]   matching device...
	[  299.190560] > __driver_attach(dev=ed9a3e10, data=bf06dd24)
	[  299.196062]   matching device...
	[  299.199301] > __driver_attach(dev=ed9a4010, data=bf06dd24)
	[  299.204799]   matching device...
	[  299.208051] > __driver_attach(dev=ed9a4210, data=bf06dd24)
	[  299.213534]   matching device...
	[  299.216796] > __driver_attach(dev=ed9a4410, data=bf06dd24)
	[  299.222307]   matching device...
	[  299.225545] > __driver_attach(dev=ed9a4610, data=bf06dd24)
	[  299.231060]   matching device...
	[  299.234295] > __driver_attach(dev=ed9a4810, data=bf06dd24)
	[  299.239798]   matching device...
	[  299.243051] > __driver_attach(dev=ed9a4a10, data=bf06dd24)
	[  299.248534]   matching device...
	[  299.251799] > __driver_attach(dev=ed9a4c10, data=bf06dd24)
	[  299.257309]   matching device...
	[  299.260548] > __driver_attach(dev=ed9a4e10, data=bf06dd24)
	[  299.266064]   matching device...
	[  299.269298] > __driver_attach(dev=ed9a5010, data=bf06dd24)
	[  299.274801]   matching device...
	[  299.278054] > __driver_attach(dev=ed9a5210, data=bf06dd24)
	[  299.283537]   matching device...
	[  299.286799] > __driver_attach(dev=ed9a5410, data=bf06dd24)
	[  299.292311]   matching device...
	[  299.295549] > __driver_attach(dev=ed9a5610, data=bf06dd24)
	[  299.301064]   matching device...
	[  299.304296] > __driver_attach(dev=ed9a5810, data=bf06dd24)
	[  299.309800]   matching device...
	[  299.313054] > __driver_attach(dev=ed9a5a10, data=bf06dd24)
	[  299.318537]   matching device...
	[  299.321808]   done
	[  299.323821]   locking parent...
	[  299.326991]   done
	[  299.329007]   locking device...
	[  299.332191]   done
	[  299.334201]   probing device...
	[  299.337372] bus: 'platform': driver_probe_device: matched device 70030000.hda with driver tegra-hda
	[  299.346453] bus: 'platform': really_probe: probing driver tegra-hda with device 70030000.hda
	[  299.354990] devices_kset: Moving 70030000.hda to end of list
	[  299.510965] device: 'hdaudioC0D3': device_add
	[  299.590057] > __hda_codec_driver_register(drv=bf0795f0, name=snd_hda_codec_hdmi, owner=bf079680)
	[  299.598862] > driver_register(drv=bf0795f0)
	[  299.603054]   finding driver...
	[  299.606206]   adding driver...
	[  299.609265] > __driver_attach(dev=ede27c00, data=bf0795f0)
	[  299.614756]   matching device...
	[  299.617998] > hda_bus_match(dev=ede27c00, drv=bf0795f0)
	[  299.623240] > hda_codec_match(dev=ede27c00, drv=bf0795f0)
	[  299.628657] < hda_codec_match() match!
	[  299.632429]   done
	[  299.634443]   locking parent...

It hangs here, but interestingly I can interrupt it using Ctrl-C:

	^C[  329.774183] > __device_attach_driver(drv=bf0795f0, _data=ecbc3d08)
	[  329.780536]   matching device...
	[  329.783844] > hda_bus_match(dev=ede27c00, drv=bf0795f0)
	[  329.789198] > hda_codec_match(dev=ede27c00, drv=bf0795f0)
	[  329.794722] < hda_codec_match() match!
	[  329.798600]   async allowed: 0
	[  329.801790] bus: 'hdaudio': driver_probe_device: matched device hdaudioC0D3 with driver snd_hda_codec_hdmi
	[  329.811577] bus: 'hdaudio': really_probe: probing driver snd_hda_codec_hdmi with device hdaudioC0D3
	[  329.820913] devices_kset: Moving hdaudioC0D3 to end of list
	[  329.826618] > hda_codec_driver_probe(dev=ede27c00)
	[  329.831533]   device: hdaudioC0D3
	[  329.835152] > patch_tegra_hdmi(codec=ede27c00)
	[  329.916075] < patch_tegra_hdmi()
	[  329.920029] ALSA pcmC0D3p,0:HDMI 0: cannot preallocate for size 65536

	[  330.946327] < hda_codec_driver_probe()
	[  330.950122] driver: 'snd_hda_codec_hdmi': driver_bound: bound to device 'hdaudioC0D3'
	[  330.958115] bus: 'hdaudio': really_probe: bound device hdaudioC0D3 to driver snd_hda_codec_hdmi
	[  330.966903] < __device_attach_driver() = 1
	[  330.971179] device: 'card0': device_add
	[  330.975432] device: 'controlC0': device_add
	[  330.981325] device: 'pcmC0D3p': device_add
	[  330.987256] device: 'input1': device_add
	[  330.991997] input: tegra-hda HDMI/DP,pcm=3 as /devices/soc0/70030000.hda/sound/card0/input1
	[  331.000477] device: 'event1': device_add
	[  331.136299] driver: 'tegra-hda': driver_bound: bound to device '70030000.hda'
	[  331.143621] bus: 'platform': really_probe: bound device 70030000.hda to driver tegra-hda
	[  331.151804]   done
	[  331.153845]   unlocking device...
	[  331.157288]   done
	[  331.157473]   done
	[  331.157483]   locking device...
	[  331.157493]   done
	[  331.157501]   unlocking device...
	[  331.157508]   done
	[  331.157514]   unlocking parent...
	[  331.157522]   done
	[  331.157532] < __driver_attach()
	[  331.157714]   adding groups...
	[  331.157722]   sending KOBJ_ADD event...
	[  331.157772] < driver_register() = 0
	[  331.157784] < __hda_codec_driver_register() = 0
	[  331.196006]   unlocking parent...
	[  331.199354]   done
	[  331.201407] < __driver_attach()
	[  331.204551] > __driver_attach(dev=ed9a5c10, data=bf06dd24)
	[  331.210061]   matching device...
	[  331.213325] > __driver_attach(dev=ed9a5e10, data=bf06dd24)
	[  331.218826]   matching device...
	[  331.222091] > __driver_attach(dev=ed9a6010, data=bf06dd24)
	[  331.227593]   matching device...
	[  331.230837] > __driver_attach(dev=ed9a6210, data=bf06dd24)
	[  331.236341]   matching device...
	[  331.239578] > __driver_attach(dev=ed9a6410, data=bf06dd24)
	[  331.245079]   matching device...
	[  331.248351] > __driver_attach(dev=ed9a6610, data=bf06dd24)
	[  331.253854]   matching device...
	[  331.257119] > __driver_attach(dev=ed9a6810, data=bf06dd24)
	[  331.262623]   matching device...
	[  331.265901] > __driver_attach(dev=ed9a6a10, data=bf06dd24)
	[  331.271407]   matching device...
	[  331.274645] > __driver_attach(dev=ed9a6c10, data=bf06dd24)
	[  331.280146]   matching device...
	[  331.283411] > __driver_attach(dev=ed9a6e10, data=bf06dd24)
	[  331.288913]   matching device...
	[  331.292178] > __driver_attach(dev=ed9a7010, data=bf06dd24)
	[  331.297681]   matching device...
	[  331.300955] > __driver_attach(dev=ed9a7210, data=bf06dd24)
	[  331.306459]   matching device...
	[  331.309696] > __driver_attach(dev=ed9a7410, data=bf06dd24)
	[  331.315197]   matching device...
	[  331.318461] > __driver_attach(dev=ed9a7610, data=bf06dd24)
	[  331.323964]   matching device...
	[  331.327229] > __driver_attach(dev=ed9a7810, data=bf06dd24)
	[  331.332732]   matching device...
	[  331.335993] > __driver_attach(dev=ed9a7a10, data=bf06dd24)
	[  331.341497]   matching device...
	[  331.344734] > __driver_attach(dev=ed9a7c10, data=bf06dd24)
	[  331.350236]   matching device...
	[  331.353502] > __driver_attach(dev=ed9a7e10, data=bf06dd24)
	[  331.359005]   matching device...
	[  331.362269] > __driver_attach(dev=ed9b0010, data=bf06dd24)
	[  331.367772]   matching device...
	[  331.371032] > __driver_attach(dev=ed9b0210, data=bf06dd24)
	[  331.376533]   matching device...
	[  331.379771] > __driver_attach(dev=ed9b0410, data=bf06dd24)
	[  331.385272]   matching device...
	[  331.388536] > __driver_attach(dev=ed9b0610, data=bf06dd24)
	[  331.394039]   matching device...
	[  331.397312] > __driver_attach(dev=ed9b0810, data=bf06dd24)
	[  331.402816]   matching device...
	[  331.406068] > __driver_attach(dev=ed9b0a10, data=bf06dd24)
	[  331.411569]   matching device...
	[  331.414807] > __driver_attach(dev=ed9b0c10, data=bf06dd24)
	[  331.420307]   matching device...
	[  331.423572] > __driver_attach(dev=ed9b0e10, data=bf06dd24)
	[  331.429074]   matching device...
	[  331.432339] > __driver_attach(dev=ed9b1010, data=bf06dd24)
	[  331.437841]   matching device...
	[  331.441092] > __driver_attach(dev=ed9b1210, data=bf06dd24)
	[  331.446600]   matching device...
	[  331.449836] > __driver_attach(dev=ed9b1410, data=bf06dd24)
	[  331.455339]   matching device...
	[  331.458604] > __driver_attach(dev=edad2410, data=bf06dd24)
	[  331.464105]   matching device...
	[  331.467368] > __driver_attach(dev=edcbb810, data=bf06dd24)
	[  331.472870]   matching device...
	[  331.476120] > __driver_attach(dev=edde4a10, data=bf06dd24)
	[  331.481625]   matching device...
	[  331.484863] > __driver_attach(dev=edde5210, data=bf06dd24)
	[  331.490366]   matching device...
	[  331.493630] > __driver_attach(dev=edde5410, data=bf06dd24)
	[  331.499133]   matching device...
	[  331.502384] > __driver_attach(dev=edde5610, data=bf06dd24)
	[  331.507879]   matching device...
	[  331.511129] > __driver_attach(dev=edde5810, data=bf06dd24)
	[  331.516623]   matching device...
	[  331.519855] > __driver_attach(dev=edde5a10, data=bf06dd24)
	[  331.525348]   matching device...
	[  331.528598] > __driver_attach(dev=ede78810, data=bf06dd24)
	[  331.534092]   matching device...
	[  331.537341] > __driver_attach(dev=edeb5e10, data=bf06dd24)
	[  331.542838]   matching device...
	[  331.546133]   adding groups...
	[  331.549184]   sending KOBJ_ADD event...
	[  331.553043] < driver_register() = 0

Thierry
Kevin Hilman Sept. 11, 2015, 5:08 p.m. UTC | #15 
Thierry Reding <thierry.reding@gmail.com> writes:

> On Fri, Sep 11, 2015 at 05:59:48PM +0200, Thierry Reding wrote:
>> On Fri, Sep 11, 2015 at 04:51:49PM +0100, Jon Hunter wrote:
>> > 
>> > On 11/09/15 14:25, Thierry Reding wrote:
>> > 
>> > [snip]
>> > 
>> > > Works for me 100% of the time. Unloading and reloading isn't a problem
>> > > either. What revision of the Jetson TK1 do you have? Mine is a C.2
>> > 
>> > Unfortunately, I am not sure it is whatever is in Paul's automation rig
>> > [0]. However, I have also reproduced this on a tegra124 nyan-big in the
>> > office.
>> 
>> I was able to reproduce this using a busybox initial ramdisk. Just to
>> make sure I built a separate one from git and it exposes the same
>> behaviour. I suspect that this is some sort of weird interaction between
>> mdev and async probing and nobody's noticed so far because async probing
>> isn't very common (at least in the ARM world).
>> 
>> I'll be off for the weekend soonish, but I'll try to find some more time
>> next week to track this down.
>
> Before I head into the weekend, here are my findings: looks like this
> might be some sort of recursive locking problem. Here's the output with
> a lot of debug messages:

FWIW, in kernelci we use a buildroot initramfs[1] with eudev enabled for
module loading.  Before booting, modules are injected into the ramdisk
so they are loaded during boot by eudev.

The source is on github[2] and can be rebuilt using './configs/frags/build armel'

Kevin

[1] http://storage.kernelci.org/images/rootfs/buildroot/armel/
[2] https://github.com/kernelci/buildroot/tree/kernelci/2015.02
Thierry Reding Sept. 17, 2015, 10:26 a.m. UTC | #16 
On Fri, Sep 11, 2015 at 10:08:06AM -0700, Kevin Hilman wrote:
> Thierry Reding <thierry.reding@gmail.com> writes:
> 
> > On Fri, Sep 11, 2015 at 05:59:48PM +0200, Thierry Reding wrote:
> >> On Fri, Sep 11, 2015 at 04:51:49PM +0100, Jon Hunter wrote:
> >> > 
> >> > On 11/09/15 14:25, Thierry Reding wrote:
> >> > 
> >> > [snip]
> >> > 
> >> > > Works for me 100% of the time. Unloading and reloading isn't a problem
> >> > > either. What revision of the Jetson TK1 do you have? Mine is a C.2
> >> > 
> >> > Unfortunately, I am not sure it is whatever is in Paul's automation rig
> >> > [0]. However, I have also reproduced this on a tegra124 nyan-big in the
> >> > office.
> >> 
> >> I was able to reproduce this using a busybox initial ramdisk. Just to
> >> make sure I built a separate one from git and it exposes the same
> >> behaviour. I suspect that this is some sort of weird interaction between
> >> mdev and async probing and nobody's noticed so far because async probing
> >> isn't very common (at least in the ARM world).
> >> 
> >> I'll be off for the weekend soonish, but I'll try to find some more time
> >> next week to track this down.
> >
> > Before I head into the weekend, here are my findings: looks like this
> > might be some sort of recursive locking problem. Here's the output with
> > a lot of debug messages:
> 
> FWIW, in kernelci we use a buildroot initramfs[1] with eudev enabled for
> module loading.  Before booting, modules are injected into the ramdisk
> so they are loaded during boot by eudev.
> 
> The source is on github[2] and can be rebuilt using './configs/frags/build armel'

This turned out to be rather interesting. The reason why I wasn't seeing
this on my setup was because request_module() ends up directly calling
the /sbin/modprobe userspace helper. On my setup I had these files
installed in /usr/bin (because that's the default installation path that
kmod uses) and I was missing a symlink from /sbin to /usr/bin, therefore
causing request_module() to return with -ENOENT. Unfortunately the HDA
core code completely ignores errors from request_module() so didn't give
any indication at all. Thanks to Jon Hunter who put me on that trail.

After fixing the root filesystem I was seeing the deadlocks as well. But
the root cause of this was now clearly the request_module(). It turns
out that this causes the driver for the HDA codec to be bound to the HDA
codec device immediately, from within the HDA controller's ->probe()
callback, hence leading to the deadlock.

That's a known problem in HDA land and for Intel this has been worked
around rather creatively by deferring HDA codec probing to a work queue
that runs asynchronously to the controller's probe. To be fair there
seem to be other reasons why this is necessary on Intel (the HDA codec
and i915 display drivers interact weirdly). It's possible that a work-
around isn't necessary on Intel anymore either because the recursive
locking of HDA controller vs. HDA codec is gone and the i915 device
should be relatively far removed to not cause any deadlocks. I haven't
invested any time in fixing this because I don't have a setup where I
could test this.

The solution I came up with, and I've sent patches earlier with a couple
of people from this thread Cc'ed, is to get rid of the explicit calls to
the request_module() function and use existing infrastructure instead. I
implemented a uevent callback in the HDA bus that reports the MODALIAS
information to the userspace helper, which can then use it to auto-load
the proper module. That gets rid of the recursive locking because both
devices are now probed from different contexts.

This should work just fine with any relatively modern distribution. Both
systemd and eudev implementations of udev should support loading modules
when they see a MODALIAS environment variable. For busybox this doesn't
work out of the box, but you can enable it by adding the following line
to /etc/mdev.conf:

	# support module loading on hotplug
	$MODALIAS=.*    root:root 660 @modprobe "$MODALIAS"

Make sure you have /etc/passwd and /etc/group entries for root, or else
mdev will fail to parse this file. mdev still doesn't automatically load
modules on boot (mdev -s isn't quite the same as udevadm trigger), but
that's only a minor inconvenience and maybe even expected when you use
mdev.

Given that the patches are somewhat invasive and probably need more
testing on Intel, I'm not sure if they'll make it into v4.3. If not I
suggest we go ahead and remove the problematic Kconfig option for now
(or make it built-in) and enable it again when the fixes have landed
(if not for v4.3 then hopefully for v4.4). Perhaps give it a week or so
to give the sound tree maintainers a chance to look at the patches and
evaluate whether or not they should go into v4.3.

Does that sound reasonable?

Thierry
diff mbox

Patch

diff --git a/arch/arm/configs/multi_v7_defconfig
b/arch/arm/configs/multi_v7_defconfig
index b2facab..a285afe 100644
--- a/arch/arm/configs/multi_v7_defconfig
+++ b/arch/arm/configs/multi_v7_defconfig
@@ -468,7 +468,6 @@  CONFIG_FRAMEBUFFER_CONSOLE_ROTATION=y
 CONFIG_SOUND=m
 CONFIG_SND=m
 CONFIG_SND_DYNAMIC_MINORS=y
-CONFIG_SND_HDA_TEGRA=m
 CONFIG_SND_HDA_INPUT_BEEP=y
 CONFIG_SND_HDA_PATCH_LOADER=y
 CONFIG_SND_HDA_CODEC_REALTEK=m