netdev - e1000e: 1 second spins in e1000_acquire_swflag

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Message-ID: <20130526164634.GA7241@lintop.rgmadvisors.com>
Date:	Sun, 26 May 2013 11:46:34 -0500
From:	Shawn Bohrer <shawn.bohrer@...il.com>
To:	e1000-devel@...ts.sourceforge.net
Cc:	netdev@...r.kernel.org
Subject: e1000e: 1 second spins in e1000_acquire_swflag_ich8lan?

My laptop was struggling to play youtube videos this morning so I took
a peek in top and noticed the watchdog/1 thread hogging my CPU.  Next
step I take a peek with perf:

49.57%   kworker/1:1  [kernel.kallsyms]                   [k] native_read_tsc
         |
         --- native_read_tsc
            |
            |--92.49%-- delay_tsc
            |          __const_udelay
            |          e1000_acquire_swflag_ich8lan
            |          e1000e_read_phy_reg_igp
            |          e1000e_phy_has_link_generic
            |          e1000_check_for_copper_link_ich8lan
            |          e1000e_has_link
            |          e1000_watchdog_task
            |          process_one_work
            |          worker_thread
            |          kthread
            |          ret_from_fork

Alright, so we're callingn udelay from e1000_acquire_swflag_ich8lan.
How often and for how long?  I take a look with trace-cmd:

kworker/1:2-23734 [001]  3971.629095: funcgraph_entry:                   |    e1000_acquire_swflag_ich8lan() {
kworker/1:2-23734 [001]  3971.629098: funcgraph_entry:      ! 999.674 us |      delay_tsc();
kworker/1:2-23734 [001]  3971.630100: funcgraph_entry:      ! 999.639 us |      delay_tsc();
kworker/1:2-23734 [001]  3971.631101: funcgraph_entry:      ! 999.639 us |      delay_tsc();
<snip>...<snip>
kworker/1:2-23734 [001]  3972.630995: funcgraph_exit:       ! 1001899 us |    }

So I see it calls mdelay(1) over and over again for a total of 1
second.  Looks like I'm getting stuck in this bit of code where
SW_FLAG_TIMEOUT is 1 second:

        timeout = SW_FLAG_TIMEOUT;

        extcnf_ctrl |= E1000_EXTCNF_CTRL_SWFLAG;
        ew32(EXTCNF_CTRL, extcnf_ctrl);

        while (timeout) {
                extcnf_ctrl = er32(EXTCNF_CTRL);
                if (extcnf_ctrl & E1000_EXTCNF_CTRL_SWFLAG)
                        break;

                mdelay(1);
                timeout--;
        }

I guess I have two questions:  

1) Do these need to be mdelays instead of msleeps?  It looks like in
my case this is called from process context, but I didn't audit all of
the callers of this function and maybe it can happen from interrupt
context too?

2) Any idea why I'm hitting this in the first place?

$ lspci | grep Ether
00:19.0 Ethernet controller: Intel Corporation 82566MM Gigabit Network Connection (rev 03)
$ ethtool -i eth0
driver: e1000e
version: 2.2.14-k
firmware-version: 0.3-0
bus-info: 0000:00:19.0
supports-statistics: yes
supports-test: yes
supports-eeprom-access: yes
supports-register-dump: yes
supports-priv-flags: no
$ uname -r
3.9.3-201.fc18.x86_64

Thanks,
Shawn

--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html