2010-07-21 12:54:43

by Valdis Klētnieks

[permalink] [raw]
Subject: kernel/panic.c warn_slowpath_common printk timestamp weirdness

Seeing this on my Dell Latitude. The timestamps from the 'cut here' and
WARNING lines are different even though they're issued by sequential lines in
panic.c - but then the printk timestamps remain identical even through an
*entire second* WARN call. Is somebody blocking clock interrupts and failing
to re-enable them, or is something different going on here?

[42836.057704] IN=wlan0 OUT= MAC=ff:ff:ff:ff:ff:ff:94:44:52:1a:8f:57:08:00 SRC=192.168.2.1 DST=192.168.2.255 LEN=37 TOS=0x00 PREC=0x00 TTL=64 ID=0 DF PROTO=UDP SPT=32769 DPT=10111 LEN=17
[42860.244827] IN=wlan0 OUT= MAC=ff:ff:ff:ff:ff:ff:94:44:52:1a:8f:57:08:00 SRC=192.168.2.1 DST=192.168.2.255 LEN=37 TOS=0x00 PREC=0x00 TTL=64 ID=0 DF PROTO=UDP SPT=32769 DPT=10111 LEN=17
[42875.543219] ------------[ cut here ]------------
[42875.544006] WARNING: at lib/plist.c:57 plist_check_head+0x47/0x114()
[42875.544006] Hardware name: Latitude E6500
[42875.544006] Modules linked in: ppp_async sunrpc microcode usb_storage [last unloaded: scsi_wait_scan]
[42875.544006] Pid: 58070, comm: pulseaudio Tainted: G W 2.6.35-rc5-mmotm0719 #2
[42875.544006] Call Trace:
[42875.544006] [<ffffffff81037335>] warn_slowpath_common+0x80/0x98
[42875.544006] [<ffffffff81037362>] warn_slowpath_null+0x15/0x17
[42875.544006] [<ffffffff812051df>] plist_check_head+0x47/0x114
[42875.544006] [<ffffffff812052c7>] plist_add+0x1b/0xb1
[42875.544006] [<ffffffff81057b2e>] update_target+0x94/0xd0
[42875.544006] [<ffffffff81057d54>] pm_qos_add_request+0x79/0x7b
[42875.544006] [<ffffffff8141d199>] snd_pcm_hw_params+0x25a/0x28a
[42875.544006] [<ffffffff8141da29>] snd_pcm_common_ioctl1+0x23b/0x980
[42875.544006] [<ffffffff811c63db>] ? inode_has_perm.clone.18+0x92/0xa2
[42875.544006] [<ffffffff8141e613>] snd_pcm_playback_ioctl1+0x231/0x246
[42875.544006] [<ffffffff810d9178>] ? fd_install+0x36/0xd5
[42875.544006] [<ffffffff8141e652>] snd_pcm_playback_ioctl+0x2a/0x2e
[42875.544006] [<ffffffff810e91a0>] vfs_ioctl+0x31/0xa2
[42875.544006] [<ffffffff810e9b1f>] do_vfs_ioctl+0x496/0x4c9
[42875.544006] [<ffffffff810e9ba9>] sys_ioctl+0x57/0x96
[42875.544006] [<ffffffff8100272b>] system_call_fastpath+0x16/0x1b
[42875.544006] ---[ end trace 23d666d936caf587 ]---
[42875.544006] ------------[ cut here ]------------
[42875.544006] WARNING: at lib/plist.c:57 plist_check_head+0x47/0x114()
[42875.544006] Hardware name: Latitude E6500
[42875.544006] Modules linked in: ppp_async sunrpc microcode usb_storage [last unloaded: scsi_wait_scan]
[42875.544006] Pid: 58070, comm: pulseaudio Tainted: G W 2.6.35-rc5-mmotm0719 #2
[42875.544006] Call Trace:
[42875.544006] [<ffffffff81037335>] warn_slowpath_common+0x80/0x98
[42875.544006] [<ffffffff81037362>] warn_slowpath_null+0x15/0x17
[42875.544006] [<ffffffff812051df>] plist_check_head+0x47/0x114
[42875.544006] [<ffffffff81205354>] plist_add+0xa8/0xb1
[42875.544006] [<ffffffff81057b2e>] update_target+0x94/0xd0
[42875.544006] [<ffffffff81057d54>] pm_qos_add_request+0x79/0x7b
[42875.544006] [<ffffffff8141d199>] snd_pcm_hw_params+0x25a/0x28a
[42875.544006] [<ffffffff8141da29>] snd_pcm_common_ioctl1+0x23b/0x980
[42875.544006] [<ffffffff811c63db>] ? inode_has_perm.clone.18+0x92/0xa2
[42875.544006] [<ffffffff8141e613>] snd_pcm_playback_ioctl1+0x231/0x246
[42875.544006] [<ffffffff810d9178>] ? fd_install+0x36/0xd5
[42875.544006] [<ffffffff8141e652>] snd_pcm_playback_ioctl+0x2a/0x2e
[42875.544006] [<ffffffff810e91a0>] vfs_ioctl+0x31/0xa2
[42875.544006] [<ffffffff810e9b1f>] do_vfs_ioctl+0x496/0x4c9
[42875.544006] [<ffffffff810e9ba9>] sys_ioctl+0x57/0x96
[42875.544006] [<ffffffff8100272b>] system_call_fastpath+0x16/0x1b
[42875.544006] ---[ end trace 23d666d936caf588 ]---
[42882.427310] ------------[ cut here ]------------
[42882.428016] WARNING: at lib/plist.c:57 plist_check_head+0x47/0x114()
[42882.428016] Hardware name: Latitude E6500
[42882.428016] Modules linked in: ppp_async sunrpc microcode usb_storage [last unloaded: scsi_wait_scan]
[42882.428016] Pid: 58070, comm: pulseaudio Tainted: G W 2.6.35-rc5-mmotm0719 #2
[42882.428016] Call Trace:
[42882.428016] [<ffffffff81037335>] warn_slowpath_common+0x80/0x98
[42882.428016] [<ffffffff81037362>] warn_slowpath_null+0x15/0x17
[42882.428016] [<ffffffff812051df>] plist_check_head+0x47/0x114
[42882.428016] [<ffffffff8120537c>] plist_del+0x1f/0x8b
[42882.428016] [<ffffffff81057b21>] update_target+0x87/0xd0
[42882.428016] [<ffffffff81057bb6>] pm_qos_remove_request+0x4c/0x5c
[42882.428016] [<ffffffff8141dad9>] snd_pcm_common_ioctl1+0x2eb/0x980
[42882.428016] [<ffffffff811c63db>] ? inode_has_perm.clone.18+0x92/0xa2
[42882.428016] [<ffffffff8141e613>] snd_pcm_playback_ioctl1+0x231/0x246
[42882.428016] [<ffffffff8109589d>] ? trace_preempt_on+0x15/0x28
[42882.428016] [<ffffffff810c727e>] ? unmap_region+0xbd/0xcc
[42882.428016] [<ffffffff8141e652>] snd_pcm_playback_ioctl+0x2a/0x2e
[42882.428016] [<ffffffff810e91a0>] vfs_ioctl+0x31/0xa2
[42882.428016] [<ffffffff810e9b1f>] do_vfs_ioctl+0x496/0x4c9
[42882.428016] [<ffffffff810e9ba9>] sys_ioctl+0x57/0x96
[42882.428016] [<ffffffff810c746a>] ? unlink_file_vma+0x2d/0x4d
[42882.428016] [<ffffffff8100272b>] system_call_fastpath+0x16/0x1b
[42882.428016] ---[ end trace 23d666d936caf589 ]---
[42882.428016] ------------[ cut here ]------------
[42882.428016] WARNING: at lib/plist.c:57 plist_check_head+0x47/0x114()
[42882.428016] Hardware name: Latitude E6500
[42882.428016] Modules linked in: ppp_async sunrpc microcode usb_storage [last unloaded: scsi_wait_scan]
[42882.428016] Pid: 58070, comm: pulseaudio Tainted: G W 2.6.35-rc5-mmotm0719 #2
[42882.428016] Call Trace:
[42882.428016] [<ffffffff81037335>] warn_slowpath_common+0x80/0x98
[42882.428016] [<ffffffff81037362>] warn_slowpath_null+0x15/0x17
[42882.428016] [<ffffffff812051df>] plist_check_head+0x47/0x114
[42882.428016] [<ffffffff812053df>] plist_del+0x82/0x8b
[42882.428016] [<ffffffff81057b21>] update_target+0x87/0xd0
[42882.428016] [<ffffffff81057bb6>] pm_qos_remove_request+0x4c/0x5c
[42882.428016] [<ffffffff8141dad9>] snd_pcm_common_ioctl1+0x2eb/0x980
[42882.428016] [<ffffffff811c63db>] ? inode_has_perm.clone.18+0x92/0xa2
[42882.428016] [<ffffffff8141e613>] snd_pcm_playback_ioctl1+0x231/0x246
[42882.428016] [<ffffffff8109589d>] ? trace_preempt_on+0x15/0x28
[42882.428016] [<ffffffff810c727e>] ? unmap_region+0xbd/0xcc
[42882.428016] [<ffffffff8141e652>] snd_pcm_playback_ioctl+0x2a/0x2e
[42882.428016] [<ffffffff810e91a0>] vfs_ioctl+0x31/0xa2
[42882.428016] [<ffffffff810e9b1f>] do_vfs_ioctl+0x496/0x4c9
[42882.428016] [<ffffffff810e9ba9>] sys_ioctl+0x57/0x96
[42882.428016] [<ffffffff810c746a>] ? unlink_file_vma+0x2d/0x4d
[42882.428016] [<ffffffff8100272b>] system_call_fastpath+0x16/0x1b
[42882.428016] ---[ end trace 23d666d936caf58a ]---
[42884.623327] IN=wlan0 OUT= MAC=ff:ff:ff:ff:ff:ff:94:44:52:1a:8f:57:08:00 SRC=192.168.2.1 DST=192.168.2.255 LEN=37 TOS=0x00 PREC=0x00 TTL=64 ID=0 DF PROTO=UDP SPT=32769 DPT=10111 LEN=17
[42914.070946] IN=wlan0 OUT= MAC=ff:ff:ff:ff:ff:ff:94:44:52:1a:8f:57:08:00 SRC=192.168.2.1 DST=192.168.2.255 LEN=37 TOS=0x00 PREC=0x00 TTL=64 ID=0 DF PROTO=UDP SPT=32769 DPT=10111 LEN=17


Attachments:
(No filename) (227.00 B)

2010-07-21 13:36:46

by Arjan van de Ven

[permalink] [raw]
Subject: Re: kernel/panic.c warn_slowpath_common printk timestamp weirdness

On 7/21/2010 5:54 AM, [email protected] wrote:
> Seeing this on my Dell Latitude. The timestamps from the 'cut here' and
> WARNING lines are different even though they're issued by sequential lines in
> panic.c - but then the printk timestamps remain identical even through an
> *entire second* WARN call. Is somebody blocking clock interrupts and failing
> to re-enable them, or is something different going on here?
>
> [42875.543219] ------------[ cut here ]------------
> [42875.544006] WARNING: at lib/plist.c:57 plist_check_head+0x47/0x114()
>

> [42875.544006] WARNING: at lib/plist.c:57 plist_check_head+0x47/0x114()
> [42875.544006] Hardware name: Latitude E6500
>

> [42882.428016] ------------[ cut here ]------------
> [42882.428016] WARNING: at lib/plist.c:57 plist_check_head+0x47/0x114()
>


Maybe I have not have had coffee yet.. but I don't see the one second
jump in the three cases you mailed...

2010-07-21 17:36:50

by Valdis Klētnieks

[permalink] [raw]
Subject: Re: kernel/panic.c warn_slowpath_common printk timestamp weirdness

On Wed, 21 Jul 2010 06:36:41 PDT, Arjan van de Ven said:
> On 7/21/2010 5:54 AM, [email protected] wrote:
> > Seeing this on my Dell Latitude. The timestamps from the 'cut here' and
> > WARNING lines are different even though they're issued by sequential lines
in
> > panic.c - but then the printk timestamps remain identical even through an
> > *entire second* WARN call. Is somebody blocking clock interrupts and faili
ng
> > to re-enable them, or is something different going on here?
> >
> > [42875.543219] ------------[ cut here ]------------
> > [42875.544006] WARNING: at lib/plist.c:57 plist_check_head+0x47/0x114()
> >
>
> > [42875.544006] WARNING: at lib/plist.c:57 plist_check_head+0x47/0x114()
> > [42875.544006] Hardware name: Latitude E6500
> >
>
> > [42882.428016] ------------[ cut here ]------------
> > [42882.428016] WARNING: at lib/plist.c:57 plist_check_head+0x47/0x114()
> >
>
>
> Maybe I have not have had coffee yet.. but I don't see the one second
> jump in the three cases you mailed...

I mean the value stays nailed down, even through a second WARN call - it outputs
two entire WARN tracebacks with the exact same timestamp. Even if the same
timestamp gets used for the traceback, I'd expect the next 'cut here' to have a
new timestamp, and the second WARN trace to have a different timestamp as
well.


Attachments:
(No filename) (227.00 B)