Re: perf/nmi : NMI Dazed and confused messages on core2
From: Don Zickus
Date: Wed Nov 20 2013 - 10:11:13 EST
On Thu, Nov 14, 2013 at 04:32:28PM -0500, Vince Weaver wrote:
> Hello
>
> when running the perf_fuzzer on a core2 machine I often get the syslog
> spammed with messages like this:
>
> [ 7911.810186] Uhhuh. NMI received for unknown reason 3d on CPU 0.
> [ 7911.812756] Do you have a strange power saving mode enabled?
> [ 7911.812756] Dazed and confused, but trying to continue
> [ 7912.554225] Uhhuh. NMI received for unknown reason 2d on CPU 1.
> [ 7912.556758] Do you have a strange power saving mode enabled?
> [ 7912.556758] Dazed and confused, but trying to continue
> [ 7912.838169] Uhhuh. NMI received for unknown reason 2d on CPU 0.
> [ 7912.840726] Do you have a strange power saving mode enabled?
> [ 7912.840726] Dazed and confused, but trying to continue
>
> I've managed to narrow this down to a small program that will reproduce
> the issue (attached) although I can only get it to reproduce on a core2
> system (it doesn't work on recent atom or ivy bridge machines I have
> access to).
>
> So maybe it's just an obscure core2 problem and not worth fixing, but I
> thought I'd report it anyway.
>
> It looks like it might be related to setting up a cache event to trigger
> with high frequency while some other events are also triggering.
>
> Vince Weaver
> vincent.weaver@xxxxxxxxx
> http://www.eece.maine.edu/~vweaver/
Nice! Thanks. I'll try to reproduce and poke at this later in the week.
I actually have a core2 in my lab, hopefully this will work. I also have
another bug where someone complains that a pentium4 gets similar floods
with a 'perf record perf bench all' command. Perhaps the issues are
similar.
At least with your program I can narrow down the number of events that it
takes to cause this issue. :-) It should be more helpful to debug.
Thanks.
Cheers,
Don
> /* core2_nmi_flood.c */
> /* by Vince Weaver <vincent.weaver _at_ maine.edu */
>
> /* This code, when run in a tight loop, i.e. */
> /* while true; do ./core2_nmi_flood ; done */
> /* will lead to lots of NMI messages printed to the */
> /* syslog on a core2 machine running recent (3.12) */
> /* Linux. */
>
> /*
> [ 7911.810186] Uhhuh. NMI received for unknown reason 3d on CPU 0.
> [ 7911.812756] Do you have a strange power saving mode enabled?
> [ 7911.812756] Dazed and confused, but trying to continue
> [ 7912.554225] Uhhuh. NMI received for unknown reason 2d on CPU 1.
> [ 7912.556758] Do you have a strange power saving mode enabled?
> [ 7912.556758] Dazed and confused, but trying to continue
> [ 7912.838169] Uhhuh. NMI received for unknown reason 2d on CPU 0.
> [ 7912.840726] Do you have a strange power saving mode enabled?
> [ 7912.840726] Dazed and confused, but trying to continue
> */
>
> #define _GNU_SOURCE 1
> #include <stdio.h>
> #include <unistd.h>
> #include <fcntl.h>
> #include <string.h>
> #include <signal.h>
> #include <sys/mman.h>
> #include <sys/syscall.h>
> #include <sys/ioctl.h>
> #include <sys/prctl.h>
> #include <poll.h>
> #include <linux/hw_breakpoint.h>
> #include <linux/perf_event.h>
>
> int fd[1024];
> struct perf_event_attr pe[1024];
>
>
> long long id;
>
> struct sigaction sa;
> static int overflows=0;
>
> static void our_handler(int signum, siginfo_t *info, void *uc) {
> int fd = info->si_fd;
>
>
> ioctl(fd,PERF_EVENT_IOC_DISABLE,0);
> overflows++;
> ioctl(fd, PERF_EVENT_IOC_REFRESH,1);
> }
> int perf_event_open(struct perf_event_attr *hw_event_uptr,
> pid_t pid, int cpu, int group_fd, unsigned long flags) {
>
> return syscall(__NR_perf_event_open,hw_event_uptr, pid, cpu,
> group_fd, flags);
> }
>
> int main(int argc, char **argv) {
> /* 1 */
> /* 2 */
> /* 3 */
> /* fd = 15 */
>
> memset(&pe[15],0,sizeof(struct perf_event_attr));
> pe[15].type=PERF_TYPE_HARDWARE;
> pe[15].size=96;
> pe[15].config=PERF_COUNT_HW_CACHE_REFERENCES;
> pe[15].sample_period=0xf2;
> pe[15].sample_type=PERF_SAMPLE_TID|PERF_SAMPLE_ADDR|PERF_SAMPLE_READ|PERF_SAMPLE_CALLCHAIN|PERF_SAMPLE_RAW|PERF_SAMPLE_STACK_USER|PERF_SAMPLE_WEIGHT;//|PERF_SAMPLE_IDENTIFIER; /* 1643a */
> pe[15].read_format=PERF_FORMAT_TOTAL_TIME_ENABLED|PERF_FORMAT_TOTAL_TIME_RUNNING|PERF_FORMAT_ID; /* 7 */
> pe[15].disabled=1;
> pe[15].pinned=1;
> pe[15].exclude_idle=1;
> pe[15].mmap=1;
> pe[15].inherit_stat=1;
> pe[15].precise_ip=0; /* arbitrary skid */
> pe[15].exclude_guest=1;
> pe[15].exclude_callchain_kernel=1;
> pe[15].exclude_callchain_user=1;
> pe[15].wakeup_events=-1037221357;
> pe[15].bp_type=HW_BREAKPOINT_EMPTY;
> pe[15].config2=0xffffffffffb24240;
> pe[15].branch_sample_type=PERF_SAMPLE_BRANCH_USER|PERF_SAMPLE_BRANCH_KERNEL|PERF_SAMPLE_BRANCH_HV|PERF_SAMPLE_BRANCH_ANY;//|PERF_SAMPLE_BRANCH_ABORT_TX|0x8101000000000000ULL;
> pe[15].sample_regs_user=-2130706432;
> pe[15].sample_stack_user=176;
>
> fd[15]=perf_event_open(&pe[15],
> 0, /* current thread */
> -1, /* all cpus */
> -1, /* New Group Leader */
> 0 /*0*/ );
>
>
> /* 4 */
> memset(&sa, 0, sizeof(struct sigaction));
> sa.sa_sigaction = our_handler;
> sa.sa_flags = SA_SIGINFO;
> if (sigaction( SIGRTMIN+2, &sa, NULL) < 0) {
> printf("Error setting up signal handler\n");
> }
> fcntl(fd[15], F_SETFL, O_RDWR|O_NONBLOCK|O_ASYNC);
> fcntl(fd[15], F_SETSIG, SIGRTMIN+2);
> fcntl(fd[15], F_SETOWN,getpid());
> /* 5 */
> /* fd = 16 */
>
> memset(&pe[16],0,sizeof(struct perf_event_attr));
> pe[16].type=PERF_TYPE_SOFTWARE;
> pe[16].config=PERF_COUNT_SW_TASK_CLOCK;
> pe[16].sample_type=0; /* 0 */
> pe[16].read_format=PERF_FORMAT_TOTAL_TIME_ENABLED|PERF_FORMAT_GROUP; /* 9 */
> pe[16].disabled=1;
> pe[16].exclusive=1;
> pe[16].exclude_user=1;
> pe[16].exclude_kernel=1;
> pe[16].exclude_hv=1;
> pe[16].task=1;
> pe[16].precise_ip=0; /* arbitrary skid */
> pe[16].mmap_data=1;
> pe[16].sample_id_all=1;
> pe[16].exclude_host=1;
> pe[16].exclude_guest=1;
> pe[16].wakeup_events=0;
> pe[16].bp_type=HW_BREAKPOINT_EMPTY;
>
> fd[16]=perf_event_open(&pe[16],
> 0, /* current thread */
> -1, /* all cpus */
> fd[11], /* 11 is group leader */
> PERF_FLAG_FD_NO_GROUP /*1*/ );
>
>
> /* 6 */
> close(fd[11]);
> /* 7 */
> /* fd = 11 */
>
> memset(&pe[11],0,sizeof(struct perf_event_attr));
> pe[11].type=PERF_TYPE_HW_CACHE;
> pe[11].config=PERF_COUNT_HW_CACHE_LL | ( PERF_COUNT_HW_CACHE_OP_READ << 8) | ( PERF_COUNT_HW_CACHE_RESULT_ACCESS << 16 );
> pe[11].sample_type=0; /* 0 */
> pe[11].read_format=PERF_FORMAT_TOTAL_TIME_ENABLED|PERF_FORMAT_ID; /* 5 */
> pe[11].inherit=1;
> pe[11].exclusive=1;
> pe[11].exclude_hv=1;
> pe[11].comm=1;
> pe[11].freq=1;
> pe[11].enable_on_exec=1;
> pe[11].precise_ip=0; /* arbitrary skid */
> pe[11].sample_id_all=1;
> pe[11].exclude_guest=1;
> pe[11].exclude_callchain_user=1;
> pe[11].wakeup_events=0;
> pe[11].bp_type=HW_BREAKPOINT_EMPTY;
>
> fd[11]=perf_event_open(&pe[11],
> 0, /* current thread */
> -1, /* all cpus */
> -1, /* New Group Leader */
> PERF_FLAG_FD_OUTPUT /*2*/ );
>
>
> /* 8 */
> /* fd = 17 */
>
> memset(&pe[17],0,sizeof(struct perf_event_attr));
> pe[17].type=PERF_TYPE_SOFTWARE;
> pe[17].size=80;
> pe[17].config=PERF_COUNT_SW_TASK_CLOCK;
> pe[17].sample_type=0; /* 0 */
> pe[17].read_format=PERF_FORMAT_TOTAL_TIME_ENABLED|PERF_FORMAT_ID; /* 5 */
> pe[17].disabled=1;
> pe[17].inherit=1;
> pe[17].exclude_idle=1;
> pe[17].comm=1;
> pe[17].freq=1;
> pe[17].inherit_stat=1;
> pe[17].enable_on_exec=1;
> pe[17].precise_ip=3; /* must have zero skid */
> pe[17].mmap_data=1;
> pe[17].sample_id_all=1;
> pe[17].exclude_guest=1;
> pe[17].exclude_callchain_kernel=1;
> pe[17].wakeup_events=0;
> pe[17].bp_type=HW_BREAKPOINT_EMPTY;
>
> fd[17]=perf_event_open(&pe[17],
> 0, /* current thread */
> -1, /* all cpus */
> -1, /* New Group Leader */
> PERF_FLAG_FD_NO_GROUP /*1*/ );
>
>
> /* 9 */
> memset(&sa, 0, sizeof(struct sigaction));
> sa.sa_sigaction = our_handler;
> sa.sa_flags = SA_SIGINFO;
> if (sigaction( SIGRTMIN+2, &sa, NULL) < 0) {
> printf("Error setting up signal handler\n");
> }
> fcntl(fd[17], F_SETFL, O_RDWR|O_NONBLOCK|O_ASYNC);
> fcntl(fd[17], F_SETSIG, SIGRTMIN+2);
> fcntl(fd[17], F_SETOWN,getpid());
> /* 10 */
> /* fd = 4 */
>
> memset(&pe[4],0,sizeof(struct perf_event_attr));
> pe[4].type=PERF_TYPE_TRACEPOINT;
> pe[4].size=96;
> pe[4].config=0x32;
> pe[4].sample_period=0xffffffffffffffff;
> pe[4].sample_type=PERF_SAMPLE_IP|PERF_SAMPLE_TIME|PERF_SAMPLE_READ|PERF_SAMPLE_STREAM_ID|PERF_SAMPLE_WEIGHT; /* 4215 */
> pe[4].read_format=PERF_FORMAT_TOTAL_TIME_ENABLED|PERF_FORMAT_TOTAL_TIME_RUNNING|PERF_FORMAT_ID|PERF_FORMAT_GROUP; /* f */
> pe[4].comm=1;
> pe[4].inherit_stat=1;
> pe[4].enable_on_exec=1;
> pe[4].task=1;
> pe[4].watermark=1;
> pe[4].precise_ip=1; /* constant skid */
> pe[4].mmap_data=1;
> pe[4].exclude_guest=1;
> pe[4].exclude_callchain_user=1;
> pe[4].wakeup_watermark=15465631;
> pe[4].bp_type=HW_BREAKPOINT_W; /*2*/
> pe[4].bp_addr=0xffff7e4b9558b75d;
> pe[4].bp_len=0x4;
> pe[4].branch_sample_type=PERF_SAMPLE_BRANCH_USER|PERF_SAMPLE_BRANCH_KERNEL|PERF_SAMPLE_BRANCH_HV|PERF_SAMPLE_BRANCH_ANY|PERF_SAMPLE_BRANCH_ANY_CALL|PERF_SAMPLE_BRANCH_ANY_RETURN|PERF_SAMPLE_BRANCH_IND_CALL;//|PERF_SAMPLE_BRANCH_ABORT_TX|PERF_SAMPLE_BRANCH_IN_TX|PERF_SAMPLE_BRANCH_NO_TX|0x8400000000006c00ULL;
> pe[4].sample_regs_user=-2918402996084736013;
> pe[4].sample_stack_user=956639924;
>
> fd[4]=perf_event_open(&pe[4],
> 0, /* current thread */
> -1, /* all cpus */
> -1, /* New Group Leader */
> PERF_FLAG_FD_NO_GROUP|PERF_FLAG_FD_OUTPUT /*3*/ );
>
>
> /* 11 */
> /* fd = 5 */
>
> memset(&pe[5],0,sizeof(struct perf_event_attr));
> pe[5].type=PERF_TYPE_HARDWARE;
> pe[5].size=96;
> pe[5].config=PERF_COUNT_HW_BRANCH_MISSES;
> pe[5].sample_type=0; /* 0 */
> pe[5].read_format=PERF_FORMAT_TOTAL_TIME_ENABLED|PERF_FORMAT_TOTAL_TIME_RUNNING|PERF_FORMAT_ID; /* 7 */
> pe[5].disabled=1;
> pe[5].inherit=1;
> pe[5].exclusive=1;
> pe[5].exclude_user=1;
> pe[5].exclude_kernel=1;
> pe[5].exclude_idle=1;
> pe[5].mmap=1;
> pe[5].comm=1;
> pe[5].freq=1;
> pe[5].enable_on_exec=1;
> pe[5].precise_ip=0; /* arbitrary skid */
> pe[5].mmap_data=1;
> pe[5].exclude_host=1;
> pe[5].wakeup_events=0;
> pe[5].bp_type=HW_BREAKPOINT_EMPTY;
>
> fd[5]=perf_event_open(&pe[5],
> 0, /* current thread */
> -1, /* all cpus */
> -1, /* New Group Leader */
> PERF_FLAG_FD_OUTPUT /*2*/ );
>
>
> /* 12 */
> /* fd = 6 */
>
> memset(&pe[6],0,sizeof(struct perf_event_attr));
> pe[6].type=PERF_TYPE_RAW;
> pe[6].size=72;
> pe[6].config=0x808000004240580a;
> pe[6].sample_type=0; /* 0 */
> pe[6].read_format=PERF_FORMAT_TOTAL_TIME_ENABLED|PERF_FORMAT_TOTAL_TIME_RUNNING; /* 3 */
> pe[6].inherit=1;
> pe[6].exclusive=1;
> pe[6].exclude_hv=1;
> pe[6].mmap=1;
> pe[6].freq=1;
> pe[6].task=1;
> pe[6].watermark=1;
> pe[6].precise_ip=0; /* arbitrary skid */
> pe[6].sample_id_all=1;
> pe[6].exclude_host=1;
> pe[6].exclude_guest=1;
> pe[6].exclude_callchain_kernel=1;
> pe[6].wakeup_watermark=0;
> pe[6].bp_type=HW_BREAKPOINT_EMPTY;
>
> fd[6]=perf_event_open(&pe[6],
> 0, /* current thread */
> -1, /* all cpus */
> -1, /* New Group Leader */
> PERF_FLAG_FD_NO_GROUP|PERF_FLAG_FD_OUTPUT /*3*/ );
>
>
> /* 13 */
> prctl(PR_TASK_PERF_EVENTS_ENABLE);
> /* 14 */
> /* fd = 8 */
>
> memset(&pe[8],0,sizeof(struct perf_event_attr));
> pe[8].type=PERF_TYPE_RAW;
> pe[8].config=0x3c21;
> pe[8].sample_type=0; /* 0 */
> pe[8].read_format=PERF_FORMAT_TOTAL_TIME_ENABLED|PERF_FORMAT_TOTAL_TIME_RUNNING; /* 3 */
> pe[8].disabled=1;
> pe[8].exclude_hv=1;
> pe[8].mmap=1;
> pe[8].comm=1;
> pe[8].inherit_stat=1;
> pe[8].task=1;
> pe[8].precise_ip=0; /* arbitrary skid */
> pe[8].exclude_host=1;
> pe[8].exclude_callchain_kernel=1;
> pe[8].wakeup_events=0;
> pe[8].bp_type=HW_BREAKPOINT_EMPTY;
>
> fd[8]=perf_event_open(&pe[8],
> 0, /* current thread */
> -1, /* all cpus */
> fd[18], /* 18 is group leader */
> PERF_FLAG_FD_NO_GROUP /*1*/ );
>
>
> /* 15 */
> prctl(PR_TASK_PERF_EVENTS_DISABLE);
> /* 16 */
> /* fd = 20 */
>
> memset(&pe[20],0,sizeof(struct perf_event_attr));
> pe[20].type=PERF_TYPE_RAW;
> pe[20].config=0xc0ffffffe65b1a09;
> pe[20].sample_type=0; /* 0 */
> pe[20].read_format=PERF_FORMAT_TOTAL_TIME_ENABLED|PERF_FORMAT_TOTAL_TIME_RUNNING; /* 3 */
> pe[20].exclusive=1;
> pe[20].exclude_user=1;
> pe[20].exclude_kernel=1;
> pe[20].exclude_hv=1;
> pe[20].mmap=1;
> pe[20].comm=1;
> pe[20].watermark=1;
> pe[20].precise_ip=0; /* arbitrary skid */
> pe[20].sample_id_all=1;
> pe[20].exclude_host=1;
> pe[20].exclude_guest=1;
> pe[20].exclude_callchain_kernel=1;
> pe[20].wakeup_watermark=0;
> pe[20].bp_type=HW_BREAKPOINT_EMPTY;
>
> fd[20]=perf_event_open(&pe[20],
> 0, /* current thread */
> -1, /* all cpus */
> -1, /* New Group Leader */
> PERF_FLAG_FD_NO_GROUP /*1*/ );
>
>
> /* 17 */
> /* fd = 21 */
>
> memset(&pe[21],0,sizeof(struct perf_event_attr));
> pe[21].type=PERF_TYPE_SOFTWARE;
> pe[21].config=PERF_COUNT_SW_TASK_CLOCK;
> pe[21].sample_type=0; /* 0 */
> pe[21].read_format=PERF_FORMAT_TOTAL_TIME_ENABLED|PERF_FORMAT_GROUP; /* 9 */
> pe[21].pinned=1;
> pe[21].exclude_user=1;
> pe[21].exclude_idle=1;
> pe[21].inherit_stat=1;
> pe[21].enable_on_exec=1;
> pe[21].watermark=1;
> pe[21].precise_ip=1; /* constant skid */
> pe[21].mmap_data=1;
> pe[21].sample_id_all=1;
> pe[21].exclude_host=1;
> pe[21].exclude_callchain_user=1;
> pe[21].wakeup_watermark=0;
> pe[21].bp_type=HW_BREAKPOINT_EMPTY;
>
> fd[21]=perf_event_open(&pe[21],
> 0, /* current thread */
> -1, /* all cpus */
> -1, /* New Group Leader */
> 0xffff880c00000000ULL /*ffff880c00000000*/ );
>
>
> /* 18 */
> /* fd = 22 */
>
> memset(&pe[22],0,sizeof(struct perf_event_attr));
> pe[22].type=PERF_TYPE_SOFTWARE;
> pe[22].size=72;
> pe[22].config=PERF_COUNT_SW_TASK_CLOCK;
> pe[22].sample_type=0; /* 0 */
> pe[22].read_format=PERF_FORMAT_TOTAL_TIME_RUNNING; /* 2 */
> pe[22].disabled=1;
> pe[22].pinned=1;
> pe[22].mmap=1;
> pe[22].freq=1;
> pe[22].inherit_stat=1;
> pe[22].precise_ip=0; /* arbitrary skid */
> pe[22].mmap_data=1;
> pe[22].sample_id_all=1;
> pe[22].exclude_guest=1;
> pe[22].exclude_callchain_kernel=1;
> pe[22].exclude_callchain_user=1;
> pe[22].wakeup_events=0;
> pe[22].bp_type=HW_BREAKPOINT_EMPTY;
>
> fd[22]=perf_event_open(&pe[22],
> getpid(), /* current thread */
> -1, /* all cpus */
> -1, /* New Group Leader */
> 0 /*0*/ );
>
>
> /* 19 */
> close(fd[16]);
> /* 20 */
> prctl(PR_TASK_PERF_EVENTS_ENABLE);
> /* 21 */
> prctl(PR_TASK_PERF_EVENTS_DISABLE);
> /* Replayed 21 syscalls */
> return 0;
> }
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/