port-i386/43007: kernel preemption in NMI handler (tprof shows inaccurate results on MP system)

[irino%src.ricoh.co.jp@localhost]

>Number:         43007
>Category:       port-i386
>Synopsis:       kernel preemption in NMI handler (tprof shows inaccurate 
>results on MP system)
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    port-i386-maintainer
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Fri Mar 19 07:30:01 +0000 2010
>Originator:     IRINO yoshiaki
>Release:        NetBSD-5.0.2
>Organization:
RICOH COMPANY, LTD.
>Environment:
NetBSD  5.0.2 NetBSD 5.0.2 (GENERIC_TPROF) #1: Mon Mar 15 14:58:42 JST 2010  
root@:/usr/src/sys/arch/i386/compile/GENERIC_TPROF i386
>Description:
I modified tprof module (src/sys/arch/x86/x86/tprof_pmi.c) to work 
on Core2Duo CPU. But the tprof offten shows inaccurate result
(large "emptybuf" value), and sometimes cause kernel assertion fail
("KASSERT((pcint & LAPIC_LVT_MASKED) != 0)").
I tried to trace this problem by using debug-ful (== with many 
breakpoints) kernel. This kernel's backtrace shows a rdmsr() in 
tprof_pmi_nmi() was interrupted by clock interrupt, and kernel 
preemption occurred in the NMI handler context.
If the preempted context was resumed on the same CPU core later, 
tprof counts emptybuf. Because the CPU's performace counter is not 
reloaded for long seconds in heavy loaded system.
If the preempted context was resumed on the other CPU core, kernel 
assertion may occur. 
Because the other CPU's performance counter may be not yet fired.

---
fatal breakpoing trap in supervisor mode
trap type 1 code 0 eip c055f6fc cs 8 eflags 202 cr2 80a5000 ilevel 7
Stopped in pid 4.78 (np1) at netbsd:breakpoint+0x4: popl %ebp
db{0}> bt
breakpoint(ccc64eac,1,96d0,0,8,0,800000a,ccc64cc0,c0b27bc0,ccc5cc2c,ccc64cc0) 
at netbsd:breakpoint+0x4
cpu_need_resched(c0b27bc0,4,0,a,ccc64d54,ccc64cc0,ccc64cc0,c0b27bc0,ccc5cc2c,ccc64cc0)
 at netbsd:cpu_need_resched+0xf2
sched_tick(c0b27bc0,0,0,0,0,cb39c780,ccc5cc8c,c01013b7,ccc5cc2c,ccc5cc2c) at 
netbsd:sched_tick+0xd1
hardclock(ccc5cc2c,ccc5cc2c,0,0,0,0,1100,0,0,0) at netbsd:hardclock+0xbb
DDB lost frame for netbsd:Xresume_lapic_ltimer+0x27, trying 0xcbbfcf74
Xresume_lapic_ltimer() at netbsd:Xresume_lapic_ltimer+0x27
--- interrupt ---
--- switch to interrupt stack ---
rdmsr(ccc5cd48,cca8c868,c0ceda54,13,ccc5cd00,ccc5cccc,ccc5cd00,c04baf18,ccc5cccc,9)
 at netbsd:rdmsr+0x6
trap() at netbsd:trap+0x20b
--- trap (number 9) ---
0x804911c:
db{0}> continue
fatal breakpoint trap in supervisor mode
...
db{0}> bt
...
kpreempt(c055f68e)
...
trap() at netbsd:trap+0x20b
--- trap (number 9) ---
0x804911c:
db{0}>

0xc055f688 <rdmsr>:     mov    0x4(%esp),%ecx
0xc055f68c <rdmsr+4>:   rdmsr  
0xc055f68e <rdmsr+6>:   ret    
0xc055f68f <rdmsr+7>:   nop    
0xc055f690 <wrmsr>:     mov    0x4(%esp),%ecx
0xc055f694 <wrmsr+4>:   mov    0x8(%esp),%eax
0xc055f698 <wrmsr+8>:   mov    0xc(%esp),%edx
0xc055f69c <wrmsr+12>:  wrmsr  
0xc055f69e <wrmsr+14>:  ret    
0xc055f69f <wrmsr+15>:  nop    
---
>How-To-Repeat:
Enable kernel's tprof module and make /usr/sbin/tprof command.
Prepare multi-threaded and "hogging the CPU" program.
% /usr/sbin/tprof -o /dev/null  program

If you need my modified kernel code and/or test program, 
I can send them.
>Fix:
This patch worked fine for me, but I am not sure that all 
T_NMI must be executed in interrupt disabled state or not.
% diff -c src/sys/arch/i386/i386/vector.S src/sys/arch/i386/i386/vector.S.NMI
*** src/sys/arch/i386/i386/vector.S     Thu Sep 24 16:21:27 2009
--- src/sys/arch/i386/i386/vector.S.NMI Fri Mar 19 14:47:19 2010
***************
*** 841,847 ****
  IDTVEC(trap01)
        BPTTRAP(T_TRCTRAP)
  IDTVEC(trap02)
!       ZTRAP(T_NMI)
  IDTVEC(trap03)
        BPTTRAP(T_BPTFLT)
  IDTVEC(trap04)
--- 841,850 ----
  IDTVEC(trap01)
        BPTTRAP(T_TRCTRAP)
  IDTVEC(trap02)
!       pushl $0
!       pushl $(T_NMI)
!       INTRENTRY
!       jmp _C_LABEL(calltrap)
  IDTVEC(trap03)
        BPTTRAP(T_BPTFLT)
  IDTVEC(trap04)