linux kernel debug 之 CallTrace

这篇文章是基于上次UWB(WUSB) wireless debug 的一个问题，然后引申出来的一个话题，对kenel有一定理解的同学可能会有一定的帮助。

--其实这个问题，个人认为，这个个CallTrace会一起down机，cpuhold的等问题，还是一个很大的问题。不过从一般意义上来讲，他是个warning我们可以不用管他。但谁让自己是做技术的呢，没办法，眼里容不得沙子。来吧干货。

1.      Kernel int request & free

Call Trace:

Apr  7 10:44:56 magic kernel: ------------[ cuthere ]------------

Apr  7 10:44:56 magic kernel: WARNING: atkernel/softirq.c:159 local_bh_enable_ip+0x7d/0xb0() (Tainted: P           ---------------   )

Apr  7 10:44:56 magic kernel: Hardware name: HPZ420 Workstation

Apr  7 10:44:56 magic kernel: Modules linked in:usb_skeleton(U) wusb_cbaf(U) elok_s(P)(U) tun bridge iptable_mangle iptable_natnf_nat nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 iptable_filter ip_tablessunrpc bnx2fc cnic uio fcoe libfcoe 8021q garp stp libfc llc scsi_transport_fcscsi_tgt cpufreq_ondemand acpi_cpufreq freq_table mperf ipv6 rcim2usb(U)psysdrv(P)(U) esdcan_pci200(P)(U) realtek_uwb(U) vfat fat hwa_hc(U) wusb_wa(U)ext3 wusbcore(U) jbd hwa_rc(U) uwb(U) wmi xhci_hcd nvidia(P)(U) igb dca ptppps_core sg microcode serio_raw i2c_i801 i2c_core iTCO_wdt iTCO_vendor_supportsnd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdepsnd_seq snd_seq_device snd_pcm snd_timer snd soundcore snd_page_alloc e1000eshpchp ext4 mbcache jbd2 sd_mod crc_t10dif sr_mod cdrom firewire_ohcifirewire_core crc_itu_t isci libsas mpt2sas scsi_transport_sas raid_class ahcipata_acpi ata_generic dm_mirror dm_region_hash dm_log dm_mod [last unloaded:scsi_wait_scan]

Apr  7 10:44:56 magic kernel: Pid: 6127, comm:java Tainted: P          ---------------   2.6.32-358.11.1.el6.x86_64 #1

Apr  7 10:44:56 magic kernel: Call Trace:

Apr  7 10:44:56 magic kernel: <IRQ>  [<ffffffff8106e2e7>] ? warn_slowpath_common+0x87/0xc0

Apr  7 10:44:56 magic kernel:[<ffffffff8106e33a>] ? warn_slowpath_null+0x1a/0x20

Apr  7 10:44:56 magic kernel:[<ffffffff810778dd>] ? local_bh_enable_ip+0x7d/0xb0

Apr  7 10:44:56 magic kernel:[<ffffffff815106db>] ? _spin_unlock_bh+0x1b/0x20

Apr  7 10:44:56 magic kernel:[<ffffffffa0bcd8f7>] ? uwb_rc_set_drp_cmd_done+0x67/0x100 [uwb]

Apr  7 10:44:56 magic kernel:[<ffffffff8108107d>] ? del_timer+0x7d/0xe0

Apr  7 10:44:56 magic kernel:[<ffffffffa0bd0e95>] ? uwb_rc_neh_cb+0x25/0x40 [uwb]

Apr  7 10:44:56 magic kernel:[<ffffffffa0bd11a2>] ? uwb_rc_neh_grok+0x252/0x4d0 [uwb]

Apr  7 10:44:56 magic kernel:[<ffffffffa01e6e39>] ? hwarc_neep_cb+0x59/0x168 [hwa_rc]

Apr  7 10:44:56 magic kernel:[<ffffffff813b4ad4>] ? usb_hcd_giveback_urb+0x64/0xe0

Apr  7 10:44:56 magic kernel:[<ffffffffa0c6a26e>] ? xhci_irq+0x4be/0x17f0 [xhci_hcd]

Apr  7 10:44:56 magic kernel:[<ffffffff81082128>] ? add_timer+0x18/0x30

Apr  7 10:44:56 magic kernel:[<ffffffff810e70ea>] ? __rcu_process_callbacks+0x25a/0x350

Apr  7 10:44:56 magic kernel:[<ffffffffa0c6b5d1>] ? xhci_msi_irq+0x31/0x40 [xhci_hcd]

Apr  7 10:44:56 magic kernel:[<ffffffff810e1670>] ? handle_IRQ_event+0x60/0x170

Apr  7 10:44:56 magic kernel:[<ffffffff8107700f>] ? __do_softirq+0x11f/0x1e0

Apr  7 10:44:56 magic kernel:[<ffffffff810e3dbe>] ? handle_edge_irq+0xde/0x180

Apr  7 10:44:56 magic kernel:[<ffffffff8100de89>] ? handle_irq+0x49/0xa0

Apr  7 10:44:56 magic kernel:[<ffffffff815171bc>] ? do_IRQ+0x6c/0xf0

Apr  7 10:44:56 magic kernel: [<ffffffff8100b9d3>]? ret_from_intr+0x0/0x11

Apr  7 10:44:56 magic kernel: <EOI>

Apr  7 10:44:56 magic kernel: ---[ end trace580801de7dc9f3db ]---

Apr  7 10:44:56 magic kernel: in uwb_rsv_timer

结合Call Trace，我们上相应内核代码：

static inline void _local_bh_enable_ip(unsignedlong ip)

{

         WARN_ON_ONCE(in_irq()|| irqs_disabled());

#ifdef CONFIG_TRACE_IRQFLAGS

         local_irq_disable();

#endif

         /*

          * Are softirqs going to be turned on now:

          */

         if(softirq_count() == SOFTIRQ_DISABLE_OFFSET)

                   trace_softirqs_on(ip);

         /*

          * Keep preemption disabled until we are donewith

          * softirq processing:

         */

         sub_preempt_count(SOFTIRQ_DISABLE_OFFSET- 1);

 

         if(unlikely(!in_interrupt() && local_softirq_pending()))

                   do_softirq();

 

         dec_preempt_count();

#ifdef CONFIG_TRACE_IRQFLAGS

         local_irq_enable();

#endif

         preempt_check_resched();

}

 

warning是由WARN_ON_ONCE(in_irq()|| irqs_disabled());代码产生的

 

解决方法

解决了disconnect CallTrace

/drivers/usb/host/hwa-hc.c

static void hwahc_disconnect(structusb_interface *usb_iface)

{

       struct usb_hcd *usb_hcd;

       struct wusbhc *wusbhc;

       struct hwahc *hwahc;

 

       printk("in hwahc_disconnect\n");

 

       usb_hcd = usb_get_intfdata(usb_iface);

       wusbhc = usb_hcd_to_wusbhc(usb_hcd);

       hwahc = container_of(wusbhc, struct hwahc, wusbhc);

 

 

       wusbhc_b_destroy(&hwahc->wusbhc);

       usb_remove_hcd(usb_hcd);

       hwahc_destroy(hwahc);

       usb_put_hcd(usb_hcd);

}

 

static int hwahc_probe(struct usb_interface*usb_iface,

                       const structusb_device_id *id)

{

                   …

                   usb_hcd->wireless= 1;

       usb_hcd->irq= -1;

                   …

}

 

以上解决了disconnect的问题。

2.      Memory page alloc & free

Call Trace

Jun 11 03:09:14magic kernel: [  263.849177]  [<ffffffff81137d09>] ?free_pages+0x49/0x50

Jun 11 03:09:14magic kernel: [  263.849186]  [<ffffffffa01949b2>] ? hwarc_neep_release+0x32/0x40[hwa_rc]

Jun 11 03:09:14magic kernel: [  263.849202]  [<ffffffffa0359f7b>] ? uwb_rc_rm+0x3b/0xd0 [uwb]

Jun 11 03:09:14magic kernel: [  263.849211]  [<ffffffffa01940a1>] ?hwarc_disconnect+0x41/0x70 [hwa_rc]

Jun 11 03:09:14magic kernel: [  263.849225]  [<ffffffff813d5998>] ?usb_unbind_interface+0x78/0x160

Jun 11 03:09:14magic kernel: [  263.849235]  [<ffffffff8137407f>] ?__device_release_driver+0x6f/0xe0

Jun 11 03:09:14magic kernel: [  263.849241]  [<ffffffff813741ed>] ?device_release_driver+0x2d/0x40

Jun 11 03:09:14magic kernel: [  263.849248]  [<ffffffff813730f3>] ?bus_remove_device+0xa3/0x110

Jun 11 03:09:14magic kernel: [  263.849258]  [<ffffffff81370b2d>] ?device_del+0x12d/0x1e0

Jun 11 03:09:14magic kernel: [  263.849266]  [<ffffffff813d1c50>] ?usb_disable_device+0xb0/0x2b0

Jun 11 03:09:14magic kernel: [  263.849273]  [<ffffffff813ca862>] ?usb_disconnect+0xa2/0x1c0

Jun 11 03:09:14magic kernel: [  263.849280]  [<ffffffff813cc6fe>] ?hub_thread+0x75e/0x1820

Jun 11 03:09:14magic kernel: [  263.849291]  [<ffffffff8100969d>] ?__switch_to+0x7d/0x340

Jun 11 03:09:14magic kernel: [  263.849304]  [<ffffffff810a1460>] ?autoremove_wake_function+0x0/0x40

Jun 11 03:09:14magic kernel: [  263.849311]  [<ffffffff813cbfa0>] ?hub_thread+0x0/0x1820

Jun 11 03:09:14magic kernel: [  263.849320]  [<ffffffff810a0fce>] ?kthread+0x9e/0xc0

Jun 11 03:09:14magic kernel: [  263.849327]  [<ffffffff8100c28a>] ?child_rip+0xa/0x20

Jun 11 03:09:14 magickernel: [  263.849336]  [<ffffffff810a0f30>] ? kthread+0x0/0xc0

Jun 11 03:09:14magic kernel: [  263.849341]  [<ffffffff8100c280>] ?child_rip+0x0/0x20

Jun 11 03:09:14magic kernel: [  263.849345] Disablinglock debugging due to kernel taint

 

/drivers/uwb /hwa-rc.c

staticvoid hwarc_neep_release(struct uwb_rc *rc)

{

        struct hwarc *hwarc = rc->priv;

 

        usb_kill_urb(hwarc->neep_urb);

        usb_free_urb(hwarc->neep_urb);

        printk("%srd_buffer=%p\n",__func__, hwarc->rd_buffer);

        if (hwarc->rd_buffer != NULL){

                printk("%srd_buffer=%p\n",__func__, hwarc->rd_buffer);

                free_page((unsigned long)hwarc->rd_buffer);

                hwarc->rd_buffer = NULL;

        }

}

 

 

staticint hwarc_post_reset(struct usb_interface *iface)

{

        struct hwarc *hwarc = NULL;

        ssleep(1);

        hwarc = usb_get_intfdata(iface);

        if(hwarc == NULL){

                printk("hwarc_post_reset:ERROR hwarc is NULL in hwarc_post_reset\n");

                return 0;

        }

        struct uwb_rc *uwb_rc =hwarc->uwb_rc;

 

        return uwb_rc_post_reset(uwb_rc);

}

以上解决了内核Page free的问题。

 

3.      Kernellock

Call Trace

…

About the Spin lock. Kernel lock:mutex_lock  semaphore_lock  spin_lock atomic_lock

/drivers/uwb/drp.c  +913

static voiduwb_rc_set_drp_cmd_done(struct uwb_rc *rc, void *arg,

                                    structuwb_rceb *reply, ssize_t reply_size)

{

        struct uwb_rc_evt_set_drp_ie *r =(struct uwb_rc_evt_set_drp_ie *)reply;

        unsigned long flags;

        printk("inuwb_rc_set_drp_cmd_done!!!!!!!!\n");

 

        if (r != NULL) {

                if (r->bResultCode !=UWB_RC_RES_SUCCESS)

                       dev_err(&rc->uwb_dev.dev, "SET-DRP-IE failed: %s(%d)\n",

                                uwb_rc_strerror(r->bResultCode),r->bResultCode);

        } else

               dev_err(&rc->uwb_dev.dev, "SET-DRP-IE: timeout\n");

 

        //spin_lock_bh(&rc->rsvs_lock);

       spin_lock_irqsave(&rc->rsvs_lock, flags);

        if (rc->set_drp_ie_pending > 1) {

                rc->set_drp_ie_pending = 0;

                uwb_rsv_queue_update(rc);

        } else {

                rc->set_drp_ie_pending = 0;

        }

        spin_unlock_irqrestore(&rc->rsvs_lock, flags);

        //spin_unlock_bh(&rc->rsvs_lock);

}

 

以上解决了内核锁嵌套问题！