From owner-freebsd-current@FreeBSD.ORG Tue Sep 27 00:33:39 2011 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 06CFE1065675; Tue, 27 Sep 2011 00:33:39 +0000 (UTC) (envelope-from adrian.chadd@gmail.com) Received: from mail-gy0-f182.google.com (mail-gy0-f182.google.com [209.85.160.182]) by mx1.freebsd.org (Postfix) with ESMTP id 958288FC1E; Tue, 27 Sep 2011 00:33:38 +0000 (UTC) Received: by gyf2 with SMTP id 2so5959780gyf.13 for ; Mon, 26 Sep 2011 17:33:38 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=mime-version:sender:in-reply-to:references:date :x-google-sender-auth:message-id:subject:from:to:cc:content-type; bh=c1qJL8gBo07Pd32PPuGC0p9S+d06qEMxm5yeFFeALOg=; b=Hyw3Shyd6ojCLwtVf4dEu0zNT/MCPTZGYzaSpgtSlGUFnD9DL8+uhJ9J/zHwWBQa5X Tz0zPrG61MF72GuWz4BXWBr5of6bVqzckBgyp4MVq0840NgbP+xG32ZqphynWXpAHYCV 7pNXVpRe5E84FUOWHFSki+6G6iTv2PziuFRw0= MIME-Version: 1.0 Received: by 10.236.129.165 with SMTP id h25mr43484003yhi.38.1317083617872; Mon, 26 Sep 2011 17:33:37 -0700 (PDT) Sender: adrian.chadd@gmail.com Received: by 10.236.111.42 with HTTP; Mon, 26 Sep 2011 17:33:37 -0700 (PDT) In-Reply-To: <201109261305.57602.jhb@freebsd.org> References: <201109261053.30410.jhb@freebsd.org> <201109261305.57602.jhb@freebsd.org> Date: Tue, 27 Sep 2011 08:33:37 +0800 X-Google-Sender-Auth: 11WUORF_u_t2NnHvdXLVd9eolw8 Message-ID: From: Adrian Chadd To: John Baldwin Content-Type: text/plain; charset=ISO-8859-1 Cc: Alexander Motin , freebsd-current@freebsd.org Subject: Re: ath / 802.11n performance issues and timer code X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 27 Sep 2011 00:33:39 -0000 I spoke with John last night. This little gem popped up in the KTR trace. * the scheduler switches to the idle task * The interrupt comes in for ath0 * it gets added to the run queue * .. but then the idle task keeps running .. * .. until an arge0 interrupt comes in. There's also three statclock ticks too, in quick succession. Mav/John: the trace is at http://people.freebsd.org/~adrian/ath/ktr.4.sorted.txt . This includes KTR_SCHED, KTR_PROC, KTR_SPARE2 and KTR_INTR. Adrian 5772 (0x80907000) 2173896521 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.453: mi_switch: new thread 100026 (td_sched 0x809072e8, pid 11, int2 arge0) 5773 (0x80907000) 2173896836 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_intr.c.1253: intr_event_execute_handlers: pid 11 exec 0x803665b8(0xc087d000) for arge0 flg=80000000 5774 (0x80907000) 2173929763 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.435: mi_switch: old thread 100026 (td_sched 0x809072e8, pid 11, int2 arge0) 5775 (0x80907000) 2173929941 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.443: KTRGRAPH group:"thread", id:"int2 arge0 tid 100026", state:"iwait", attributes: prio:8, wmesg:"(null)", lockname:"(null)" 5776 (0x80907000) 2173930059 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.259: KTRGRAPH group:"load", id:"global load", counter:0, attributes: none 5777 (0x80629c80) 2173930552 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.450: KTRGRAPH group:"thread", id:"idle tid 100002", state:"running", attributes: prio:255 5778 (0x80629c80) 2173930690 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.453: mi_switch: new thread 100002 (td_sched 0x80629f68, pid 10, idle) 5779 (0x80629c80) 2173931360 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clocksource.c.762: idle at 0: now 4606.6f61caa4e07acc40 5780 (0x80629c80) 2173932827 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_intr.c.1426: intr_event_handle: exec 0x803641a4(0x80908180) for pcib0 5781 (0x80629c80) 2173933777 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_intr.c.914: intr_event_schedule_thread: schedule pid 11 (pci intr0: ath0) 5782 (0x80629c80) 2173933969 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.1314: KTRGRAPH group:"thread", id:"pci intr0: ath0 tid 100023", state:"runq add", attributes: prio:8, linkedto:"idle tid 100002" 5783 (0x80629c80) 2173934091 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.1316: KTRGRAPH group:"thread", id:"idle tid 100002", point:"wokeup", attributes: linkedto:"pci intr0: ath0 tid 100023" 5784 (0x80629c80) 2173934402 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.251: KTRGRAPH group:"load", id:"global load", counter:1, attributes: none 5785 (0x80629c80) 2173935012 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clocksource.c.266: skip at 0: 85 5786 (0x80629c80) 2173935793 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clocksource.c.312: next at 0: next 4606.853c3a57fce2f2be by 0 5787 (0x80629c80) 2173935909 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clocksource.c.428: load at 0: next 4606.853c3a57fce2f2be eq 0 5788 (0x80629c80) 2179937582 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_intr.c.1426: intr_event_handle: exec 0x803652e8(0xc087d000) for arge0 5789 (0x80629c80) 2179938312 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_intr.c.914: intr_event_schedule_thread: schedule pid 11 (int2 arge0) 5790 (0x80629c80) 2179938447 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.1314: KTRGRAPH group:"thread", id:"int2 arge0 tid 100026", state:"runq add", attributes: prio:8, linkedto:"idle tid 100002" 5791 (0x80629c80) 2179938569 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.1316: KTRGRAPH group:"thread", id:"idle tid 100002", point:"wokeup", attributes: linkedto:"int2 arge0 tid 100026" 5792 (0x80629c80) 2179938719 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.251: KTRGRAPH group:"load", id:"global load", counter:2, attributes: none 5793 (0x80629c80) 2179939169 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clocksource.c.791: active at 0: now 4606.73a77ad6245cfbb0 5794 (0x80629c80) 2179939379 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clocksource.c.186: handle at 0: now 4606.73a77ad6245cfbb0 5795 (0x80629c80) 2179942746 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clock.c.748: KTRGRAPH group:"thread", id:"idle tid 100002", point:"statclock", attributes: prio:255, stathz:127 5796 (0x80629c80) 2179943526 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clock.c.748: KTRGRAPH group:"thread", id:"idle tid 100002", point:"statclock", attributes: prio:255, stathz:127 5797 (0x80629c80) 2179943866 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clock.c.748: KTRGRAPH group:"thread", id:"idle tid 100002", point:"statclock", attributes: prio:255, stathz:127 5798 (0x80629c80) 2179944443 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clocksource.c.312: next at 0: next 4606.73d3c7a7dc1e5786 by 0 5799 (0x80629c80) 2179944558 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_clocksource.c.428: load at 0: next 4606.73d3c7a7dc1e5786 eq 0 5800 (0x80629c80) 2179945325 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.435: mi_switch: old thread 100002 (td_sched 0x80629f68, pid 10, idle) 5801 (0x80629c80) 2179945457 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.439: KTRGRAPH group:"thread", id:"idle tid 100002", state:"idle", attributes: prio:255 5802 (0x80907960) 2179946103 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.450: KTRGRAPH group:"thread", id:"pci intr0: ath0 tid 100023", state:"running", attributes: prio:8 5803 (0x80907960) 2179946255 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.453: mi_switch: new thread 100023 (td_sched 0x80907c48, pid 11, pci intr0: ath0) 5804 (0x80907960) 2179946715 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_intr.c.1253: intr_event_execute_handlers: pid 11 exec 0x80081d74(0x80904000) for ath0 flg=80000000 5805 (0x80907960) 2179952661 /data/freebsd/mips/if_ath_tx/src/sys/kern/subr_sleepqueue.c.812: sleepq_signal(0x80987900, 0) 5806 (0x80907960) 2179953387 /data/freebsd/mips/if_ath_tx/src/sys/kern/subr_sleepqueue.c.744: sleepq_wakeup: thread 0x80907640 (pid 0, ath0 taskq) 5807 (0x80907960) 2179953835 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.1314: KTRGRAPH group:"thread", id:"ath0 taskq tid 100024", state:"runq add", attributes: prio:8, linkedto:"pci intr0: ath0 tid 100023" 5808 (0x80907960) 2179953957 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.1316: KTRGRAPH group:"thread", id:"pci intr0: ath0 tid 100023", point:"wokeup", attributes: linkedto:"ath0 taskq tid 100024" 5809 (0x80907960) 2179954293 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.251: KTRGRAPH group:"load", id:"global load", counter:3, attributes: none 5810 (0x80907960) 2179955303 /data/freebsd/mips/if_ath_tx/src/sys/kern/subr_sleepqueue.c.812: sleepq_signal(0x80987900, 0) 5811 (0x80907960) 2179955841 /data/freebsd/mips/if_ath_tx/src/sys/kern/subr_sleepqueue.c.812: sleepq_signal(0x80987900, 0) 5812 (0x80907960) 2179956742 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.435: mi_switch: old thread 100023 (td_sched 0x80907c48, pid 11, pci intr0: ath0) 5813 (0x80907960) 2179956875 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.443: KTRGRAPH group:"thread", id:"pci intr0: ath0 tid 100023", state:"iwait", attributes: prio:8, wmesg:"(null)", lockname:"(null)" 5814 (0x80907960) 2179956990 /data/freebsd/mips/if_ath_tx/src/sys/kern/sched_4bsd.c.259: KTRGRAPH group:"load", id:"global load", counter:2, attributes: none 5815 (0x80907000) 2179957488 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.450: KTRGRAPH group:"thread", id:"int2 arge0 tid 100026", state:"running", attributes: prio:8 5816 (0x80907000) 2179957598 /data/freebsd/mips/if_ath_tx/src/sys/kern/kern_synch.c.453: mi_switch: new thread 100026 (td_sched 0x809072e8, pid 11, int2 arge0)