linux-kernel - Re: [PATCH v4 0/2]: perf: reduce data loss when profiling highly parallel CPU bound workloads

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-prev] [thread-next>] [day] [month] [year] [list]

Date:   Tue, 28 Aug 2018 14:43:17 -0500
From:   Kim Phillips <kim.phillips@....com>
To:     Alexey Budankov <alexey.budankov@...ux.intel.com>
Cc:     Ingo Molnar <mingo@...nel.org>,
        Peter Zijlstra <peterz@...radead.org>,
        Arnaldo Carvalho de Melo <acme@...nel.org>,
        Alexander Shishkin <alexander.shishkin@...ux.intel.com>,
        Jiri Olsa <jolsa@...hat.com>,
        Namhyung Kim <namhyung@...nel.org>,
        Andi Kleen <ak@...ux.intel.com>,
        linux-kernel <linux-kernel@...r.kernel.org>
Subject: Re: [PATCH v4 0/2]: perf: reduce data loss when profiling highly
 parallel CPU bound workloads

On Tue, 28 Aug 2018 18:44:57 +0300
Alexey Budankov <alexey.budankov@...ux.intel.com> wrote:

> Experiment with profiling matrix multiplication code executing 128 
> threads on Intel Xeon Phi (KNM) with 272 cores, like below,
> demonstrates data loss metrics value of 98%:

So I took these two patches for a quick test-drive on intel-pt.

BEFORE (acme's today's perf/core branch):

$ sudo perf version
perf version 4.18.rc7.g55fc647
$ sudo perf record -e intel_pt//  dd if=/dev/zero of=/dev/null count=100000
100000+0 records in
100000+0 records out
51200000 bytes (51 MB, 49 MiB) copied, 0.0868081 s, 590 MB/s
[ perf record: Woken up 21 times to write data ]
[ perf record: Captured and wrote 41.302 MB perf.data ]
$ 

AFTER (== BEFORE + these two patches):

$ sudo ./perf version
perf version 4.18.rc7.gbc1c99
$ sudo perf record -e intel_pt//  dd if=/dev/zero of=/dev/null count=100000
100000+0 records in
100000+0 records out
51200000 bytes (51 MB, 49 MiB) copied, 0.0931142 s, 550 MB/s

...and it's still running, minutes afterwards.  Before I kill it,
here's some strace output:

nanosleep({tv_sec=0, tv_nsec=500000}, NULL) = 0
lseek(3, 332556518, SEEK_SET)           = 332556518
write(3, "D\0\0\0\0\0\10\0", 8)         = 8
lseek(3, 0, SEEK_CUR)                   = 332556526
futex(0x7f221e7252c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
nanosleep({tv_sec=0, tv_nsec=500000}, NULL) = 0
lseek(3, 332578462, SEEK_SET)           = 332578462
write(3, "D\0\0\0\0\0\10\0", 8)         = 8
lseek(3, 0, SEEK_CUR)                   = 332578470
futex(0x7f221e7252cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
nanosleep({tv_sec=0, tv_nsec=500000}, NULL) = 0
lseek(3, 332598822, SEEK_SET)           = 332598822
write(3, "D\0\0\0\0\0\10\0", 8)         = 8
lseek(3, 0, SEEK_CUR)                   = 332598830
futex(0x7f221e7252c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e725200, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f221e7252cc, FUTEX_WAKE_PRIVATE, 1) = 1
^Cstrace: Process 3597 detached

I can't prove that it's these two patches that create the hang, but
this does look like a livelock situation...hm, hitting ^C doesn't stop
it...had to kill -9 it...erm, does 'perf record -e intel_pt// dd...'
work for you on a more standard machine?:

$ dmesg | grep Perf
[    0.044226] Performance Events: PEBS fmt3+, Skylake events, 32-deep LBR, full-width counters, Intel PMU driver.

Thanks,

Kim