Bug happens when try connect with my phone via kbluetooth (kde
application for bluetooth):
[ 114.896824] BUG: scheduling while atomic: swapper/0/0x10000100
[ 114.896831] Modules linked in: i915 drm i2c_algo_bit i2c_core
rfcomm l2cap vboxnetflt vboxdrv xt_tcpudp xt_limit xt_state
iptable_nat nf_nat nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4
iptable_filter ip_tables x_tables aes_i586 aes_generic cbc dm_crypt
dm_snapshot dm_mirror dm_region_hash dm_log dm_mod hp_wmi fuse sbp2
loop btusb bluetooth snd_hda_codec_si3054 snd_hda_codec_analog
snd_hda_intel snd_hda_codec arc4 snd_pcm_oss snd_mixer_oss snd_pcm ecb
snd_seq_dummy snd_seq_oss snd_seq_midi iwl3945 snd_rawmidi iwlcore
snd_seq_midi_event rfkill firmware_class snd_seq mac80211 snd_timer
snd_seq_device led_class pcmcia b44 ssb lib80211 uhci_hcd ehci_hcd
intel_agp psmouse snd ohci1394 mii cfg80211 usbcore agpgart
yenta_socket rsrc_nonstatic pcmcia_core serio_raw soundcore
snd_page_alloc rtc_cmos rtc_core rtc_lib battery fan ieee1394 ac
button sg evdev
[ 114.896984]
[ 114.896990] Pid: 0, comm: swapper Not tainted (2.6.29-git12 #1) HP
Compaq nx6310 (EY501ES#AKD)
[ 114.896998] EIP: 0060:[<c029c711>] EFLAGS: 00000246 CPU: 1
[ 114.897008] EIP is at acpi_idle_enter_simple+0x151/0x1be
[ 114.897014] EAX: c04f31c0 EBX: f7073450 ECX: 00000000 EDX: 01716000
[ 114.897036] ESI: 00f706bb EDI: 00f7113c EBP: f7067f6c ESP: f7067f4c
[ 114.897042] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 114.897048] CR0: 8005003b CR2: b7fb1000 CR3: 004f7000 CR4: 000006d0
[ 114.897054] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 114.897059] DR6: ffff0ff0 DR7: 00000400
[ 114.897064] Call Trace:
[ 114.897074] [<c0310156>] ? menu_select+0x36/0xf0
[ 114.897083] [<c030f3bf>] cpuidle_idle_call+0x6f/0xd0
[ 114.897091] [<c0101f15>] cpu_idle+0x55/0x90
[ 114.897099] [<c0395d38>] start_secondary+0x18d/0x205
[ 114.897107] [<c0395d38>] ? start_secondary+0x18d/0x205
dmesg:
http://unixy.pl/maciek/download/kernel/2.6.29-git12/2/dmesg-2.6.29-git12.txt
config:
http://unixy.pl/maciek/download/kernel/2.6.29-git12/config-2.6.29-git12.txt
--
Maciej Rutecki
http://www.maciek.unixy.pl
Hi Dave,
> > On Fri, 10 Apr 2009, Maciej Rutecki wrote:
> >> 2009/4/10 Thomas Gleixner <[email protected]>:
> >>
> >> [...]
> >> > Please upload trace.bz2 file to some place.
> >>
> >> http://unixy.pl/maciek/download/kernel/2.6.30-rc1-git3/laptop/trace-2.6.30-rc1-git3.bz2
> >
> > Ok. That gives us the necessary information:
> >
> > <idle>-0 1d... 76597263us : do_softirq <-irq_exit
> > <idle>-0 1d... 76597263us : __do_softirq <-do_softirq
> > <idle>-0 1..s. 76597264us : tasklet_action <-__do_softirq
> > <idle>-0 1..s. 76597265us : hci_rx_task <-tasklet_action
> > <idle>-0 1..s. 76597266us : _read_lock <-hci_rx_task
> > <idle>-0 1..s. 76597267us : skb_dequeue <-hci_rx_task
> > <idle>-0 1..s. 76597268us : _spin_lock_irqsave <-skb_dequeue
> > <idle>-0 1d.s. 76597269us : _spin_unlock_irqrestore <-skb_dequeue
> > <idle>-0 1..s. 76597270us : hci_send_to_sock <-hci_rx_task
> > <idle>-0 1..s. 76597270us+: _read_lock <-hci_send_to_sock
> > <idle>-0 1..s. 76597272us : skb_clone <-hci_send_to_sock
> > <idle>-0 1..s. 76597273us : kmem_cache_alloc <-skb_clone
> > <idle>-0 1..s. 76597274us : __skb_clone <-skb_clone
> > <idle>-0 1..s. 76597275us : __copy_skb_header <-__skb_clone
> > <idle>-0 1..s. 76597276us : skb_push <-hci_send_to_sock
> > <idle>-0 1..s. 76597277us : sock_queue_rcv_skb <-hci_send_to_sock
> > <idle>-0 1..s. 76597278us : sk_filter <-sock_queue_rcv_skb
> > <idle>-0 1..s. 76597279us : security_sock_rcv_skb <-sk_filter
> > <idle>-0 1..s. 76597280us : cap_socket_sock_rcv_skb <-security_sock_rcv_skb
> > <idle>-0 1..s. 76597280us : local_bh_disable <-sk_filter
> > <idle>-0 1..s. 76597281us : local_bh_enable <-sk_filter
> > <idle>-0 1..s. 76597282us : skb_queue_tail <-sock_queue_rcv_skb
> > <idle>-0 1..s. 76597283us : _spin_lock_irqsave <-skb_queue_tail
> > <idle>-0 1d.s. 76597284us : _spin_unlock_irqrestore <-skb_queue_tail
> > <idle>-0 1..s. 76597285us : sock_def_readable <-sock_queue_rcv_skb
> > <idle>-0 1..s. 76597286us : _read_lock <-sock_def_readable
> > <idle>-0 1..s. 76597286us : __wake_up_sync_key <-sock_def_readable
> > <idle>-0 1..s. 76597287us : _spin_lock_irqsave <-__wake_up_sync_key
> > <idle>-0 1d.s. 76597288us : __wake_up_common <-__wake_up_sync_key
> > <idle>-0 1d.s. 76597289us : pollwake <-__wake_up_common
> > <idle>-0 1d.s. 76597290us : default_wake_function <-pollwake
> > <idle>-0 1d.s. 76597290us : try_to_wake_up <-default_wake_function
> > <idle>-0 1d.s. 76597292us : update_shares <-try_to_wake_up
> > <idle>-0 1d.s. 76597293us : walk_tg_tree <-update_shares
> > <idle>-0 1d.s. 76597294us : tg_nop <-walk_tg_tree
> > <idle>-0 1d.s. 76597294us : tg_nop <-walk_tg_tree
> > <idle>-0 1d.s. 76597295us : tg_shares_up <-walk_tg_tree
> > <idle>-0 1d.s. 76597297us : tg_nop <-walk_tg_tree
> > <idle>-0 1d.s. 76597297us : tg_shares_up <-walk_tg_tree
> > <idle>-0 1d.s. 76597298us : tg_nop <-walk_tg_tree
> > <idle>-0 1d.s. 76597299us : tg_shares_up <-walk_tg_tree
> > <idle>-0 1d.s. 76597300us : tg_nop <-walk_tg_tree
> > <idle>-0 1d.s. 76597301us : tg_shares_up <-walk_tg_tree
> > <idle>-0 1d.s. 76597302us : tg_nop <-walk_tg_tree
> > <idle>-0 1d.s. 76597303us : tg_shares_up <-walk_tg_tree
> > <idle>-0 1d.s. 76597304us : tg_shares_up <-walk_tg_tree
> > <idle>-0 1d.s. 76597305us+: task_rq_lock <-try_to_wake_up
> > <idle>-0 1d.s. 76597314us : _spin_lock <-task_rq_lock
> > <idle>-0 1d.s. 76597315us : select_task_rq_fair <-try_to_wake_up
> > <idle>-0 1d.s. 76597316us : activate_task <-try_to_wake_up
> > <idle>-0 1d.s. 76597317us : enqueue_task_fair <-activate_task
> > <idle>-0 1d.s. 76597317us : enqueue_entity <-enqueue_task_fair
> > <idle>-0 1d.s. 76597318us : update_curr <-enqueue_entity
> > <idle>-0 1d.s. 76597319us : place_entity <-enqueue_entity
> > <idle>-0 1d.s. 76597320us : enqueue_entity <-enqueue_task_fair
> > <idle>-0 1d.s. 76597321us : update_curr <-enqueue_entity
> > <idle>-0 1d.s. 76597321us : place_entity <-enqueue_entity
> > <idle>-0 1d.s. 76597322us : check_preempt_curr_idle <-try_to_wake_up
> > <idle>-0 1d.s. 76597323us : resched_task <-check_preempt_curr_idle
> > <idle>-0 1dNs. 76597324us : _spin_unlock_irqrestore <-try_to_wake_up
> > <idle>-0 1dNs. 76597325us+: _spin_unlock_irqrestore <-__wake_up_sync_key
> > <idle>-0 1.Ns. 76597326us : hci_event_packet <-hci_rx_task
> > <idle>-0 1.Ns. 76597327us : skb_pull <-hci_event_packet
> > <idle>-0 1.Ns. 76597328us : _spin_lock <-hci_event_packet
> > <idle>-0 1.Ns. 76597330us : del_timer <-hci_event_packet
> > <idle>-0 1.Ns. 76597331us : hci_conn_add_sysfs <-hci_event_packet
> > <idle>-0 1.Ns. 76597332us+: dev_set_name <-hci_conn_add_sysfs
>
> Marcel, this is caused by hci conn id changes, originally the conn id
> is like "acl:xx:xx:xx:xx:xx:xx", then it was changed to
> "hdev_name:connection_handle", yes use the handle looks better, but it
> need to be done in the event handling function.
>
> What do you think about change back to original way plus hdev_name?
> like: "hdev_name:xx:xx:xx:xx:xx:xx"
that is actually a bad idea since in theory we can have more than one
SCO connection in the end. So we should use the handle. Also with the
upcoming High Speed or Low Energy stuff we need to differentiate by the
handle since more and more connections are possible.
We should fix the real problem here and to proper reference counting for
the kobject with kref here. This code might need bigger fixing since
when it was creating for 2.4, the driver model was not present.
Feel free to propose something. I am open for ideas.
Regards
Marcel
On Sat, Apr 11, 2009 at 2:25 AM, Thomas Gleixner <[email protected]> wrote=
:
> Maciej,
>
> On Fri, 10 Apr 2009, Maciej Rutecki wrote:
>> 2009/4/10 Thomas Gleixner <[email protected]>:
>>
>> [...]
>> > Please upload trace.bz2 file to some place.
>>
>> http://unixy.pl/maciek/download/kernel/2.6.30-rc1-git3/laptop/trace-2.6.=
30-rc1-git3.bz2
>
> Ok. That gives us the necessary information:
>
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d... 76597263us : do_softirq <-irq_e=
xit
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d... 76597263us : __do_softirq <-do_=
softirq
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597264us : tasklet_action <-_=
_do_softirq
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597265us : hci_rx_task <-task=
let_action
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597266us : _read_lock <-hci_r=
x_task
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597267us : skb_dequeue <-hci_=
rx_task
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597268us : _spin_lock_irqsave=
<-skb_dequeue
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597269us : _spin_unlock_irqre=
store <-skb_dequeue
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597270us : hci_send_to_sock <=
-hci_rx_task
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597270us+: _read_lock <-hci_s=
end_to_sock
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597272us : skb_clone <-hci_se=
nd_to_sock
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597273us : kmem_cache_alloc <=
-skb_clone
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597274us : __skb_clone <-skb_=
clone
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597275us : __copy_skb_header =
<-__skb_clone
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597276us : skb_push <-hci_sen=
d_to_sock
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597277us : sock_queue_rcv_skb=
<-hci_send_to_sock
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597278us : sk_filter <-sock_q=
ueue_rcv_skb
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597279us : security_sock_rcv_=
skb <-sk_filter
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597280us : cap_socket_sock_rc=
v_skb <-security_sock_rcv_skb
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597280us : local_bh_disable <=
-sk_filter
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597281us : local_bh_enable <-=
sk_filter
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597282us : skb_queue_tail <-s=
ock_queue_rcv_skb
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597283us : _spin_lock_irqsave=
<-skb_queue_tail
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597284us : _spin_unlock_irqre=
store <-skb_queue_tail
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597285us : sock_def_readable =
<-sock_queue_rcv_skb
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597286us : _read_lock <-sock_=
def_readable
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597286us : __wake_up_sync_key=
<-sock_def_readable
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1..s. 76597287us : _spin_lock_irqsave=
<-__wake_up_sync_key
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597288us : __wake_up_common <=
-__wake_up_sync_key
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597289us : pollwake <-__wake_=
up_common
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597290us : default_wake_funct=
ion <-pollwake
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597290us : try_to_wake_up <-d=
efault_wake_function
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597292us : update_shares <-tr=
y_to_wake_up
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597293us : walk_tg_tree <-upd=
ate_shares
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597294us : tg_nop <-walk_tg_t=
ree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597294us : tg_nop <-walk_tg_t=
ree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597295us : tg_shares_up <-wal=
k_tg_tree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597297us : tg_nop <-walk_tg_t=
ree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597297us : tg_shares_up <-wal=
k_tg_tree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597298us : tg_nop <-walk_tg_t=
ree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597299us : tg_shares_up <-wal=
k_tg_tree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597300us : tg_nop <-walk_tg_t=
ree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597301us : tg_shares_up <-wal=
k_tg_tree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597302us : tg_nop <-walk_tg_t=
ree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597303us : tg_shares_up <-wal=
k_tg_tree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597304us : tg_shares_up <-wal=
k_tg_tree
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597305us+: task_rq_lock <-try=
_to_wake_up
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597314us : _spin_lock <-task_=
rq_lock
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597315us : select_task_rq_fai=
r <-try_to_wake_up
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597316us : activate_task <-tr=
y_to_wake_up
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597317us : enqueue_task_fair =
<-activate_task
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597317us : enqueue_entity <-e=
nqueue_task_fair
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597318us : update_curr <-enqu=
eue_entity
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597319us : place_entity <-enq=
ueue_entity
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597320us : enqueue_entity <-e=
nqueue_task_fair
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597321us : update_curr <-enqu=
eue_entity
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597321us : place_entity <-enq=
ueue_entity
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597322us : check_preempt_curr=
_idle <-try_to_wake_up
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1d.s. 76597323us : resched_task <-che=
ck_preempt_curr_idle
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1dNs. 76597324us : _spin_unlock_irqre=
store <-try_to_wake_up
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1dNs. 76597325us+: _spin_unlock_irqre=
store <-__wake_up_sync_key
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1.Ns. 76597326us : hci_event_packet <=
-hci_rx_task
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1.Ns. 76597327us : skb_pull <-hci_eve=
nt_packet
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1.Ns. 76597328us : _spin_lock <-hci_e=
vent_packet
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1.Ns. 76597330us : del_timer <-hci_ev=
ent_packet
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1.Ns. 76597331us : hci_conn_add_sysfs=
<-hci_event_packet
> =C2=A0<idle>-0 =C2=A0 =C2=A0 =C2=A0 1.Ns. 76597332us+: dev_set_name <-hci=
_conn_add_sysfs
Marcel, this is caused by hci conn id changes, originally the conn id
is like "acl:xx:xx:xx:xx:xx:xx", then it was changed to
"hdev_name:connection_handle", yes use the handle looks better, but it
need to be done in the event handling function.
What do you think about change back to original way plus hdev_name?
like: "hdev_name:xx:xx:xx:xx:xx:xx"
diff -uprN a/net/bluetooth/hci_conn.c b/net/bluetooth/hci_conn.c
--- a/net/bluetooth/hci_conn.c 2009-04-18 19:45:21.000000000 +0800
+++ b/net/bluetooth/hci_conn.c 2009-04-18 19:45:15.000000000 +0800
@@ -247,6 +247,8 @@ struct hci_conn *hci_conn_add(struct hci
if (hdev->notify)
hdev->notify(hdev, HCI_NOTIFY_CONN_ADD);
+ hci_conn_add_sysfs(conn);
+
tasklet_enable(&hdev->tx_task);
return conn;
diff -uprN a/net/bluetooth/hci_event.c b/net/bluetooth/hci_event.c
--- a/net/bluetooth/hci_event.c 2009-04-18 19:45:28.000000000 +0800
+++ b/net/bluetooth/hci_event.c 2009-04-18 19:45:15.000000000 +0800
@@ -878,8 +878,6 @@ static inline void hci_conn_complete_evt
} else
conn->state =3D BT_CONNECTED;
- hci_conn_add_sysfs(conn);
-
if (test_bit(HCI_AUTH, &hdev->flags))
conn->link_mode |=3D HCI_LM_AUTH;
@@ -1656,8 +1654,6 @@ static inline void hci_sync_conn_complet
if (!ev->status) {
conn->handle =3D __le16_to_cpu(ev->handle);
conn->state =3D BT_CONNECTED;
-
- hci_conn_add_sysfs(conn);
} else
conn->state =3D BT_CLOSED;
diff -uprN a/net/bluetooth/hci_sysfs.c b/net/bluetooth/hci_sysfs.c
--- a/net/bluetooth/hci_sysfs.c 2009-04-18 19:45:35.000000000 +0800
+++ b/net/bluetooth/hci_sysfs.c 2009-04-18 19:45:15.000000000 +0800
@@ -101,6 +101,7 @@ static void add_conn(struct work_struct
void hci_conn_add_sysfs(struct hci_conn *conn)
{
struct hci_dev *hdev =3D conn->hdev;
+ bdaddr_t *ba =3D &conn->dst;
BT_DBG("conn %p", conn);
@@ -108,7 +109,11 @@ void hci_conn_add_sysfs(struct hci_conn
conn->dev.class =3D bt_class;
conn->dev.parent =3D &hdev->dev;
- dev_set_name(&conn->dev, "%s:%d", hdev->name, conn->handle);
+ dev_set_name(&conn->dev,
+ "%s:%2.2X%2.2X%2.2X%2.2X%2.2X%2.2X",
+ hdev->name,
+ ba->b[5], ba->b[4], ba->b[3],
+ ba->b[2], ba->b[1], ba->b[0]);
dev_set_drvdata(&conn->dev, conn);
Maciej,
On Fri, 10 Apr 2009, Maciej Rutecki wrote:
> 2009/4/10 Thomas Gleixner <[email protected]>:
>
> [...]
> > Please upload trace.bz2 file to some place.
>
> http://unixy.pl/maciek/download/kernel/2.6.30-rc1-git3/laptop/trace-2.6.30-rc1-git3.bz2
Ok. That gives us the necessary information:
<idle>-0 1d... 76597263us : do_softirq <-irq_exit
<idle>-0 1d... 76597263us : __do_softirq <-do_softirq
<idle>-0 1..s. 76597264us : tasklet_action <-__do_softirq
<idle>-0 1..s. 76597265us : hci_rx_task <-tasklet_action
<idle>-0 1..s. 76597266us : _read_lock <-hci_rx_task
<idle>-0 1..s. 76597267us : skb_dequeue <-hci_rx_task
<idle>-0 1..s. 76597268us : _spin_lock_irqsave <-skb_dequeue
<idle>-0 1d.s. 76597269us : _spin_unlock_irqrestore <-skb_dequeue
<idle>-0 1..s. 76597270us : hci_send_to_sock <-hci_rx_task
<idle>-0 1..s. 76597270us+: _read_lock <-hci_send_to_sock
<idle>-0 1..s. 76597272us : skb_clone <-hci_send_to_sock
<idle>-0 1..s. 76597273us : kmem_cache_alloc <-skb_clone
<idle>-0 1..s. 76597274us : __skb_clone <-skb_clone
<idle>-0 1..s. 76597275us : __copy_skb_header <-__skb_clone
<idle>-0 1..s. 76597276us : skb_push <-hci_send_to_sock
<idle>-0 1..s. 76597277us : sock_queue_rcv_skb <-hci_send_to_sock
<idle>-0 1..s. 76597278us : sk_filter <-sock_queue_rcv_skb
<idle>-0 1..s. 76597279us : security_sock_rcv_skb <-sk_filter
<idle>-0 1..s. 76597280us : cap_socket_sock_rcv_skb <-security_sock_rcv_skb
<idle>-0 1..s. 76597280us : local_bh_disable <-sk_filter
<idle>-0 1..s. 76597281us : local_bh_enable <-sk_filter
<idle>-0 1..s. 76597282us : skb_queue_tail <-sock_queue_rcv_skb
<idle>-0 1..s. 76597283us : _spin_lock_irqsave <-skb_queue_tail
<idle>-0 1d.s. 76597284us : _spin_unlock_irqrestore <-skb_queue_tail
<idle>-0 1..s. 76597285us : sock_def_readable <-sock_queue_rcv_skb
<idle>-0 1..s. 76597286us : _read_lock <-sock_def_readable
<idle>-0 1..s. 76597286us : __wake_up_sync_key <-sock_def_readable
<idle>-0 1..s. 76597287us : _spin_lock_irqsave <-__wake_up_sync_key
<idle>-0 1d.s. 76597288us : __wake_up_common <-__wake_up_sync_key
<idle>-0 1d.s. 76597289us : pollwake <-__wake_up_common
<idle>-0 1d.s. 76597290us : default_wake_function <-pollwake
<idle>-0 1d.s. 76597290us : try_to_wake_up <-default_wake_function
<idle>-0 1d.s. 76597292us : update_shares <-try_to_wake_up
<idle>-0 1d.s. 76597293us : walk_tg_tree <-update_shares
<idle>-0 1d.s. 76597294us : tg_nop <-walk_tg_tree
<idle>-0 1d.s. 76597294us : tg_nop <-walk_tg_tree
<idle>-0 1d.s. 76597295us : tg_shares_up <-walk_tg_tree
<idle>-0 1d.s. 76597297us : tg_nop <-walk_tg_tree
<idle>-0 1d.s. 76597297us : tg_shares_up <-walk_tg_tree
<idle>-0 1d.s. 76597298us : tg_nop <-walk_tg_tree
<idle>-0 1d.s. 76597299us : tg_shares_up <-walk_tg_tree
<idle>-0 1d.s. 76597300us : tg_nop <-walk_tg_tree
<idle>-0 1d.s. 76597301us : tg_shares_up <-walk_tg_tree
<idle>-0 1d.s. 76597302us : tg_nop <-walk_tg_tree
<idle>-0 1d.s. 76597303us : tg_shares_up <-walk_tg_tree
<idle>-0 1d.s. 76597304us : tg_shares_up <-walk_tg_tree
<idle>-0 1d.s. 76597305us+: task_rq_lock <-try_to_wake_up
<idle>-0 1d.s. 76597314us : _spin_lock <-task_rq_lock
<idle>-0 1d.s. 76597315us : select_task_rq_fair <-try_to_wake_up
<idle>-0 1d.s. 76597316us : activate_task <-try_to_wake_up
<idle>-0 1d.s. 76597317us : enqueue_task_fair <-activate_task
<idle>-0 1d.s. 76597317us : enqueue_entity <-enqueue_task_fair
<idle>-0 1d.s. 76597318us : update_curr <-enqueue_entity
<idle>-0 1d.s. 76597319us : place_entity <-enqueue_entity
<idle>-0 1d.s. 76597320us : enqueue_entity <-enqueue_task_fair
<idle>-0 1d.s. 76597321us : update_curr <-enqueue_entity
<idle>-0 1d.s. 76597321us : place_entity <-enqueue_entity
<idle>-0 1d.s. 76597322us : check_preempt_curr_idle <-try_to_wake_up
<idle>-0 1d.s. 76597323us : resched_task <-check_preempt_curr_idle
<idle>-0 1dNs. 76597324us : _spin_unlock_irqrestore <-try_to_wake_up
<idle>-0 1dNs. 76597325us+: _spin_unlock_irqrestore <-__wake_up_sync_key
<idle>-0 1.Ns. 76597326us : hci_event_packet <-hci_rx_task
<idle>-0 1.Ns. 76597327us : skb_pull <-hci_event_packet
<idle>-0 1.Ns. 76597328us : _spin_lock <-hci_event_packet
<idle>-0 1.Ns. 76597330us : del_timer <-hci_event_packet
<idle>-0 1.Ns. 76597331us : hci_conn_add_sysfs <-hci_event_packet
<idle>-0 1.Ns. 76597332us+: dev_set_name <-hci_conn_add_sysfs
Here we call dev_set_name from tasklet context which in turn calls kmalloc.
<idle>-0 1.Ns. 76597334us+: strnlen <-string
<idle>-0 1.Ns. 76597336us : __kmalloc <-kvasprintf
<idle>-0 1.Ns. 76597337us : get_slab <-__kmalloc
<idle>-0 1.Ns. 76597338us : _cond_resched <-__kmalloc
We woke up a task above so the resched bit is set and we schedule
out from the softirq context. Bad idea :)
<idle>-0 1.Ns. 76597338us : __cond_resched <-_cond_resched
<idle>-0 1.Ns. 76597339us : schedule <-__cond_resched
<idle>-0 1.Ns. 76597340us : __schedule <-schedule
<idle>-0 1.Ns. 76597341us : rcu_qsctr_inc <-__schedule
<idle>-0 1.Ns. 76597342us : __schedule_bug <-__schedule
Marcel, can you please have a look at that ?
Thanks,
tglx
2009/4/10 Thomas Gleixner <[email protected]>:
[...]
> Please upload trace.bz2 file to some place.
http://unixy.pl/maciek/download/kernel/2.6.30-rc1-git3/laptop/trace-2.6.30-rc1-git3.bz2
Regards
--
Maciej Rutecki
http://www.maciek.unixy.pl
On Fri, 10 Apr 2009, Maciej Rutecki wrote:
> 2009/4/10 Thomas Gleixner <[email protected]>:
>
> >
> > Is this with my patch applied ?
>
> Yes. I didn't observe any change.
Hmm. Ok, so the check in do_IRQ did not trigger. That means we need to
look for some other place.
Can you please apply the patch below and set CONFIG_FUNCTION_TRACER=y.
After boot please do as root:
# mount -t debugfs debugfs /sys/kernel/debug
# echo function >/sys/kernel/debug/tracing/current_tracer
# ech0 1 >/sys/kernel/debug/tracing/options/latency-format
# echo 1 >/sys/kernel/debug/tracing/tracing_enabled
Now wait until that scheduling while atomic bug triggers. This will
stop the tracer. Now
# cat /sys/kernel/debug/tracing/trace | bzip2 >/tmp/trace.bz2
Please upload trace.bz2 file to some place.
Thanks,
tglx
----
diff --git a/kernel/sched.c b/kernel/sched.c
index 5724508..2e257bf 100644
--- a/kernel/sched.c
+++ b/kernel/sched.c
@@ -4912,6 +4912,7 @@ static noinline void __schedule_bug(struct task_struct *prev)
{
struct pt_regs *regs = get_irq_regs();
+ tracing_off();
printk(KERN_ERR "BUG: scheduling while atomic: %s/%d/0x%08x\n",
prev->comm, prev->pid, preempt_count());
(Forgot CC)
2009/4/10 Thomas Gleixner <[email protected]>:
>
> Is this with my patch applied ?
Yes. I didn't observe any change.
--
Maciej Rutecki
http://www.maciek.unixy.pl
(Forgot CC)
2009/4/10 Thomas Gleixner <[email protected]>:
>
> Is this with my patch applied ?
Yes. I didn't observe any change.
--
Maciej Rutecki
http://www.maciek.unixy.pl
On Fri, 10 Apr 2009, Maciej Rutecki wrote:
> > We have a check for that in do_softirq, but none in do_IRQ. Can you
> > please apply the patch below and test whether it triggers ?
>
> When I try connect with bluetooth, and connecting hangs, very often I
> observe high load of cpu, and system was very unresponsive. ksoftirqd
> has up to 100% load:
> http://unixy.pl/maciek/download/kernel/2.6.30-rc1-git3/laptop/img_0002.jpg
>
> After this I reboot laptop.
>
> >From syslog:
> http://unixy.pl/maciek/download/kernel/2.6.30-rc1-git3/laptop/syslog.txt
Is this with my patch applied ?
Thanks,
tglx
2009/4/10 Thomas Gleixner <[email protected]>:
> On Fri, 10 Apr 2009, Maciej Rutecki wrote:
>
>> 2009/4/10 Andrew Morton <[email protected]>
>>
>> > Did this get fixed?
>>
>> On 2.6.30-rc1-git3 still the same:
>> [ =C2=A0162.541793] BUG: scheduling while atomic: swapper/0/0x10000100
>
> Yikes.
>
> 0x10000100
> =C2=A0 =C2=A0 =C2=A0 ^----- softirq count leaked.
>
> We have a check for that in do_softirq, but none in do_IRQ. Can you
> please apply the patch below and test whether it triggers ?
When I try connect with bluetooth, and connecting hangs, very often I
observe high load of cpu, and system was very unresponsive. ksoftirqd
has up to 100% load:
http://unixy.pl/maciek/download/kernel/2.6.30-rc1-git3/laptop/img_0002.jpg
After this I reboot laptop.
>From syslog:
http://unixy.pl/maciek/download/kernel/2.6.30-rc1-git3/laptop/syslog.txt
--=20
Maciej Rutecki
http://www.maciek.unixy.pl
On Fri, 10 Apr 2009, Maciej Rutecki wrote:
> 2009/4/10 Andrew Morton <[email protected]>
>
> > Did this get fixed?
>
> On 2.6.30-rc1-git3 still the same:
> [ 162.541793] BUG: scheduling while atomic: swapper/0/0x10000100
Yikes.
0x10000100
^----- softirq count leaked.
We have a check for that in do_softirq, but none in do_IRQ. Can you
please apply the patch below and test whether it triggers ?
Thanks,
tglx
---
diff --git a/arch/x86/kernel/irq.c b/arch/x86/kernel/irq.c
index c3fe010..d164396 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -206,6 +206,7 @@ unsigned int __irq_entry do_IRQ(struct pt_regs *regs)
/* high bit used in ret_from_ code */
unsigned vector = ~regs->orig_ax;
unsigned irq;
+ int prev_count = preempt_count();
exit_idle();
irq_enter();
@@ -225,6 +226,13 @@ unsigned int __irq_entry do_IRQ(struct pt_regs *regs)
irq_exit();
+ if (unlikely(prev_count != preempt_count())) {
+ printk(KERN_ERR "huh, entered interrupt %d"
+ "with preempt_count %08x, exited with %08x?\n", irq,
+ prev_count, preempt_count());
+ preempt_count() = prev_count;
+ }
+
set_irq_regs(old_regs);
return 1;
}
2009/4/10 Andrew Morton <[email protected]>
> Did this get fixed?
On 2.6.30-rc1-git3 still the same:
[ 162.541793] BUG: scheduling while atomic: swapper/0/0x10000100
[ 162.541801] Modules linked in: i915 drm i2c_algo_bit i2c_core
rfcomm l2cap xt_tcpudp xt_limit xt_state iptable_filter
nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 ip_tables x_tables
aes_i586 aes_generic cbc dm_crypt dm_snapshot dm_mirror dm_region_hash
dm_log dm_mod hp_wmi rfkill fuse sbp2 loop btusb bluetooth
snd_hda_codec_si3054 snd_hda_codec_analog snd_hda_intel snd_hda_codec
snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_dummy snd_seq_oss
snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq pcmcia snd_timer
snd_seq_device uhci_hcd psmouse ohci1394 ehci_hcd b44 ssb intel_agp
snd yenta_socket rsrc_nonstatic pcmcia_core serio_raw ieee1394 usbcore
mii agpgart rtc_cmos rtc_core rtc_lib fan battery soundcore
snd_page_alloc button ac sg evdev
[ 162.541945]
[ 162.541952] Pid: 0, comm: swapper Not tainted (2.6.30-rc1-git3 #1)
HP Compaq nx6310 (EY501ES#AKD)
[ 162.541960] EIP: 0060:[<c029f0e1>] EFLAGS: 00000246 CPU: 1
[ 162.541973] EIP is at acpi_idle_enter_simple+0x15d/0x188
[ 162.541979] EAX: c04f31c0 EBX: 0000099b ECX: 00000000 EDX: 01716000
[ 162.541986] ESI: 00000000 EDI: f7071450 EBP: f7067f6c ESP: f7067f4c
[ 162.541992] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 162.541999] CR0: 8005003b CR2: 0819d008 CR3: 2d828000 CR4: 000006d0
[ 162.542006] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 162.542012] DR6: ffff0ff0 DR7: 00000400
[ 162.542017] Call Trace:
[ 162.542030] [<c0310f6f>] cpuidle_idle_call+0x6f/0xd0
[ 162.542039] [<c0101f15>] cpu_idle+0x55/0x90
[ 162.542048] [<c0397ac8>] start_secondary+0x18d/0x205
[ 162.542057] [<c0395d38>] ? get_cpu_cap+0x9a/0xc2
[ 175.336796] BUG: scheduling while atomic: swapper/0/0x10000100
[ 175.336805] Modules linked in: i915 drm i2c_algo_bit i2c_core
rfcomm l2cap xt_tcpudp xt_limit xt_state iptable_filter
nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 ip_tables x_tables
aes_i586 aes_generic cbc dm_crypt dm_snapshot dm_mirror dm_region_hash
dm_log dm_mod hp_wmi rfkill fuse sbp2 loop btusb bluetooth
snd_hda_codec_si3054 snd_hda_codec_analog snd_hda_intel snd_hda_codec
snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_dummy snd_seq_oss
snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq pcmcia snd_timer
snd_seq_device uhci_hcd psmouse ohci1394 ehci_hcd b44 ssb intel_agp
snd yenta_socket rsrc_nonstatic pcmcia_core serio_raw ieee1394 usbcore
mii agpgart rtc_cmos rtc_core rtc_lib fan battery soundcore
snd_page_alloc button ac sg evdev
[ 175.336948]
[ 175.336956] Pid: 0, comm: swapper Not tainted (2.6.30-rc1-git3 #1)
HP Compaq nx6310 (EY501ES#AKD)
[ 175.336964] EIP: 0060:[<c029f0e1>] EFLAGS: 00000246 CPU: 1
[ 175.336977] EIP is at acpi_idle_enter_simple+0x15d/0x188
[ 175.336984] EAX: c04f31c0 EBX: 00016912 ECX: 00000000 EDX: 01716000
[ 175.336990] ESI: 00000000 EDI: f7071450 EBP: f7067f6c ESP: f7067f4c
[ 175.336997] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 175.337003] CR0: 8005003b CR2: b7f79000 CR3: 2e75d000 CR4: 000006d0
[ 175.337010] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 175.337016] DR6: ffff0ff0 DR7: 00000400
[ 175.337021] Call Trace:
[ 175.337033] [<c0310f6f>] cpuidle_idle_call+0x6f/0xd0
[ 175.337042] [<c0101f15>] cpu_idle+0x55/0x90
[ 175.337052] [<c0397ac8>] start_secondary+0x18d/0x205
[ 175.337060] [<c0395d38>] ? get_cpu_cap+0x9a/0xc2
[ 193.254798] BUG: scheduling while atomic: swapper/0/0x10000100
[ 193.254806] Modules linked in: i915 drm i2c_algo_bit i2c_core
rfcomm l2cap xt_tcpudp xt_limit xt_state iptable_filter
nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 ip_tables x_tables
aes_i586 aes_generic cbc dm_crypt dm_snapshot dm_mirror dm_region_hash
dm_log dm_mod hp_wmi rfkill fuse sbp2 loop btusb bluetooth
snd_hda_codec_si3054 snd_hda_codec_analog snd_hda_intel snd_hda_codec
snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_dummy snd_seq_oss
snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq pcmcia snd_timer
snd_seq_device uhci_hcd psmouse ohci1394 ehci_hcd b44 ssb intel_agp
snd yenta_socket rsrc_nonstatic pcmcia_core serio_raw ieee1394 usbcore
mii agpgart rtc_cmos rtc_core rtc_lib fan battery soundcore
snd_page_alloc button ac sg evdev
[ 193.254949]
[ 193.254957] Pid: 0, comm: swapper Not tainted (2.6.30-rc1-git3 #1)
HP Compaq nx6310 (EY501ES#AKD)
[ 193.254965] EIP: 0060:[<c029f0e1>] EFLAGS: 00000246 CPU: 1
[ 193.254978] EIP is at acpi_idle_enter_simple+0x15d/0x188
[ 193.254984] EAX: c04f31c0 EBX: 000017a8 ECX: 00000000 EDX: 01716000
[ 193.254991] ESI: 00000000 EDI: f7071450 EBP: f7067f6c ESP: f7067f4c
[ 193.254997] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 193.255004] CR0: 8005003b CR2: b7f79000 CR3: 2e75d000 CR4: 000006d0
[ 193.255010] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 193.255016] DR6: ffff0ff0 DR7: 00000400
[ 193.255021] Call Trace:
[ 193.255034] [<c0310f6f>] cpuidle_idle_call+0x6f/0xd0
[ 193.255043] [<c0101f15>] cpu_idle+0x55/0x90
[ 193.255052] [<c0397ac8>] start_secondary+0x18d/0x205
[ 193.255061] [<c0395d38>] ? get_cpu_cap+0x9a/0xc2
[ 242.048045] hci_cmd_task: hci0 command tx timeout
[ 246.048973] hci_cmd_task: hci0 command tx timeout
Regards
--
Maciej Rutecki
http://www.maciek.unixy.pl
On Tue, 7 Apr 2009 09:37:37 +0200 Maciej Rutecki <[email protected]> wrote:
> Bug happens when try connect with my phone via kbluetooth (kde
> application for bluetooth):
Did this get fixed?
> [ 114.896824] BUG: scheduling while atomic: swapper/0/0x10000100
PREEMPT_ACTIVE=true
softirq_count=1
weird.
> [ 114.896831] Modules linked in: i915 drm i2c_algo_bit i2c_core
> rfcomm l2cap vboxnetflt vboxdrv xt_tcpudp xt_limit xt_state
> iptable_nat nf_nat nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4
> iptable_filter ip_tables x_tables aes_i586 aes_generic cbc dm_crypt
> dm_snapshot dm_mirror dm_region_hash dm_log dm_mod hp_wmi fuse sbp2
> loop btusb bluetooth snd_hda_codec_si3054 snd_hda_codec_analog
> snd_hda_intel snd_hda_codec arc4 snd_pcm_oss snd_mixer_oss snd_pcm ecb
> snd_seq_dummy snd_seq_oss snd_seq_midi iwl3945 snd_rawmidi iwlcore
> snd_seq_midi_event rfkill firmware_class snd_seq mac80211 snd_timer
> snd_seq_device led_class pcmcia b44 ssb lib80211 uhci_hcd ehci_hcd
> intel_agp psmouse snd ohci1394 mii cfg80211 usbcore agpgart
> yenta_socket rsrc_nonstatic pcmcia_core serio_raw soundcore
> snd_page_alloc rtc_cmos rtc_core rtc_lib battery fan ieee1394 ac
> button sg evdev
> [ 114.896984]
> [ 114.896990] Pid: 0, comm: swapper Not tainted (2.6.29-git12 #1) HP
> Compaq nx6310 (EY501ES#AKD)
> [ 114.896998] EIP: 0060:[<c029c711>] EFLAGS: 00000246 CPU: 1
> [ 114.897008] EIP is at acpi_idle_enter_simple+0x151/0x1be
> [ 114.897014] EAX: c04f31c0 EBX: f7073450 ECX: 00000000 EDX: 01716000
> [ 114.897036] ESI: 00f706bb EDI: 00f7113c EBP: f7067f6c ESP: f7067f4c
> [ 114.897042] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
> [ 114.897048] CR0: 8005003b CR2: b7fb1000 CR3: 004f7000 CR4: 000006d0
> [ 114.897054] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [ 114.897059] DR6: ffff0ff0 DR7: 00000400
> [ 114.897064] Call Trace:
> [ 114.897074] [<c0310156>] ? menu_select+0x36/0xf0
> [ 114.897083] [<c030f3bf>] cpuidle_idle_call+0x6f/0xd0
> [ 114.897091] [<c0101f15>] cpu_idle+0x55/0x90
> [ 114.897099] [<c0395d38>] start_secondary+0x18d/0x205
> [ 114.897107] [<c0395d38>] ? start_secondary+0x18d/0x205
>
> dmesg:
> http://unixy.pl/maciek/download/kernel/2.6.29-git12/2/dmesg-2.6.29-git12.txt
>
> config:
> http://unixy.pl/maciek/download/kernel/2.6.29-git12/config-2.6.29-git12.txt
>
I already test 2.6.30-rc6, and problem seems be fixed.
Thanks
--
Maciej Rutecki
http://www.maciek.unixy.pl
