* kernel/panic.c warn_slowpath_common printk timestamp weirdness
@ 2010-07-21 12:54 Valdis.Kletnieks
2010-07-21 13:36 ` Arjan van de Ven
0 siblings, 1 reply; 3+ messages in thread
From: Valdis.Kletnieks @ 2010-07-21 12:54 UTC (permalink / raw)
To: Linus Torvalds, Arjan van de Ven; +Cc: linux-kernel
[-- Attachment #1: Type: text/plain, Size: 7263 bytes --]
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
[-- Attachment #2: Type: application/pgp-signature, Size: 227 bytes --]
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: kernel/panic.c warn_slowpath_common printk timestamp weirdness
2010-07-21 12:54 kernel/panic.c warn_slowpath_common printk timestamp weirdness Valdis.Kletnieks
@ 2010-07-21 13:36 ` Arjan van de Ven
2010-07-21 17:35 ` Valdis.Kletnieks
0 siblings, 1 reply; 3+ messages in thread
From: Arjan van de Ven @ 2010-07-21 13:36 UTC (permalink / raw)
To: Valdis.Kletnieks; +Cc: Linus Torvalds, linux-kernel
On 7/21/2010 5:54 AM, Valdis.Kletnieks@vt.edu 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...
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: kernel/panic.c warn_slowpath_common printk timestamp weirdness
2010-07-21 13:36 ` Arjan van de Ven
@ 2010-07-21 17:35 ` Valdis.Kletnieks
0 siblings, 0 replies; 3+ messages in thread
From: Valdis.Kletnieks @ 2010-07-21 17:35 UTC (permalink / raw)
To: Arjan van de Ven; +Cc: Linus Torvalds, linux-kernel
[-- Attachment #1: Type: text/plain, Size: 1358 bytes --]
On Wed, 21 Jul 2010 06:36:41 PDT, Arjan van de Ven said:
> On 7/21/2010 5:54 AM, Valdis.Kletnieks@vt.edu 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.
[-- Attachment #2: Type: application/pgp-signature, Size: 227 bytes --]
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2010-07-21 17:36 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2010-07-21 12:54 kernel/panic.c warn_slowpath_common printk timestamp weirdness Valdis.Kletnieks
2010-07-21 13:36 ` Arjan van de Ven
2010-07-21 17:35 ` Valdis.Kletnieks
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox