Message-ID: <bb3e3c6f-f4df-a182-c947-10c77c998cd1@arm.com>
Date:   Fri, 4 May 2018 18:10:44 +0100
From:   Robin Murphy <robin.murphy@....com>
To:     Kim Phillips <kim.phillips@....com>,
        Will Deacon <will.deacon@....com>
Cc:     Mark Rutland <mark.rutland@....com>, Vadim.Lomovtsev@...ium.com,
        linux-doc@...r.kernel.org, gklkml16@...il.com,
        Jan.Glauber@...ium.com, linux-kernel@...r.kernel.org,
        Robert.Richter@...ium.com, jnair@...iumnetworks.com,
        Ganapatrao Kulkarni <ganapatrao.kulkarni@...ium.com>,
        linux-arm-kernel@...ts.infradead.org
Subject: Re: [PATCH v4 2/2] ThunderX2: Add Cavium ThunderX2 SoC UNCORE PMU
 driver

Hi Kim,

On 04/05/18 01:30, Kim Phillips wrote:
> On Tue, 1 May 2018 12:54:05 +0100
> Will Deacon <will.deacon@....com> wrote:
> 
>> Hi Kim,
> 
> Hi Will, thanks for responding.
> 
>> On Fri, Apr 27, 2018 at 11:56:25AM -0500, Kim Phillips wrote:
>>> On Fri, 27 Apr 2018 17:09:14 +0100
>>> Will Deacon <will.deacon@....com> wrote:
>>>> On Fri, Apr 27, 2018 at 10:46:29AM -0500, Kim Phillips wrote:
>>>>> On Fri, 27 Apr 2018 15:37:20 +0100
>>>>> Will Deacon <will.deacon@....com> wrote:
>>>>>> For anything under drivers/perf/, I'd prefer not to have these prints
>>>>>> and instead see efforts to improve error reporting via the perf system
>>>>>> call interface.
>>>>>
>>>>> We'd all prefer that, and for all PMU drivers, why should ones under
>>>>> drivers/perf be treated differently?
>>>>
>>>> Because they're the ones I maintain...
>>>
>>> You represent a minority on your opinion on this matter though.
>>
>> I'm not sure that's true
> 
> I haven't seen another arch/PMU driver maintainer actively oppose it
> other than you (and Mark).
> 
>> -- you tend to be the only one raising this issue;
> 
> If you're basing that on list activity, I wouldn't, since most Arm perf
> users don't subscribe to LKML.  I'm trying to represent current and
> future Arm perf users that shouldn't be expected to hang out here on
> LKML and review PMU drivers.  Couldn't tell you why PMU driver authors
> themselves don't chime in, but will note that some drivers in
> drivers/perf do print things from their event_init functions.

As a PMU driver author who *has* already invested not-inconsiderable 
time and effort in trying to explain to you the technical issues from a 
non-maintainer perspective (and is about to do so again), I can't help 
but feel rather slighted by that comment.

> Also, you have been cc'd on off-list email threads where SPE users had
> to debug the SPE driver's event_init() manually.  There are other SPE
> users I know that have had to go through the same painstaking process of
> debugging the SPE driver.  Last but not least, there's me, and I'd sure
> appreciate more verbose PMU drivers, based on my real-life performance
> monitoring experience(s).
> 
>> I think most people don't actually care one way or the other. If you know of
> 
> Like I said, I think you're limiting your audience to LKML subscribers,
> who are more amenable to being convinced they need to debug their
> kernel.
> 
>> others who care about it too then I suggest you work together as a group to
>> solve the problem in a way which is amenable to the upstream maintainers.
> 
> I know a few off-list people that would like a more user-friendly Arm
> perf experience, but we're not qualified to solve the larger problem
> that perf has had since its inception, and I think it's a little unfair
> for you to suggest that, esp. given you're one of the maintainers, and
> there's Linus on top of you.
> 
>> Then you won't have to worry about fixing it personally. You could even
>> propose a topic for plumbers if there is enough interest in a general
>> framework for propagating error messages to userspace.
> 
> I'm not worried about fixing it personally or not.  I'm worried about
> our perf users' experience given your objection to using the vehicle
> already in use on other architectures and PMU drivers.
> 
> If you - or anyone else for that matter - know of a way that'll get us
> past this, by all means, say something.
> 
> If it helps, I recently asked acme if we could borrow bits from struct
> perf_event and got no response.
> 
>>>>> As you are already aware, I've personally tried to fix this problem -
>>>>> that has existed since before the introduction of the perf tool (I
>>>>> consider it a syscall-independent enhanced error interface), multiple
>>>>> times, and failed.
>>>>
>>>> Why is that my problem? Try harder?
>>>
>>> It's your problem because we're here reviewing a patch that happens to
>>> fall under your maintainership.  I'll be the first person to tell you
>>> I'm obviously incompetent and haven't been able to come up with a
>>> solution that is acceptable for everyone up to and including Linus
>>> Torvalds.  I'm just noticing a chronic usability problem that can be
>>> easily alleviated in the context of this patch review.
>>
>> I don't see how incompetence has anything to do with it and, like most
> 
> Well you told me to try harder, and I'm trying to let you know that I
> can try harder - ad infinitum - and still not get it, so telling me to
> try harder isn't going to necessarily resolve the issue.
> 
>> people (lucky gits...), I doubt Torvalds cares too deeply about PMU driver
>> internals. No arguments on the usability problem, but this ain't the fix
> 
> Like acme, I doubt Linus runs perf on real Arm h/w, so yes, I don't
> think they care that much, but if they did try to do it one day, I'd
> like to that they'd be able to have dmesg contain that extra error
> information for them.
> 
> As you know, David Howells wrote a supplemental error syscall facility
> [1], that Linus nacked (off list no less).  Does Linus care about what
> David Howells was developing it for?  I don't know, but he does have
> enough experience to know whether a certain approach to a problem is
> sustainable in his kernel or not.
> 
>> you're looking for: it's a bodge. We've been over this many times before.
> 
> I think it's OK - necessary even - until this error infrastructure
> problem perf has is fixed, and I think you're being unrealistic if you
> think it will be fixed anytime soon.
> 
>>>>> So until someone comes up with a solution that works for everyone
>>>>> up to and including Linus Torvalds (who hasn't put up a problem
>>>>> pulling PMU drivers emitting things to dmesg so far, by the way), this
>>>>> keep PMU drivers' errors silent preference of yours is unnecessarily
>>>>> impeding people trying to measure system performance on Arm based
>>>>> machines - all other archs' maintainers are fine with PMU drivers using
>>>>> dmesg.
>>>>
>>>> Good for them, although I'm pretty sure that at least the x86 folks are
>>>> against this crap too.
>>>
>>> Unfortunately, it doesn't affect them nearly as much as it does our
>>> more diverse platforms, which is why I don't think they care to do
>>> much about it.
>>
>> x86 has its fair share of PMUs too, so I don't think we're special in this
>> regard. The main difference seems to be that they have better support in
>> the perf tool for diagnosing problems.
> 
> Indeed, their software is as vertically integrated as their hardware,
> and, well, they have more people with more experience working and caring
> about perf running and being more usable.

I note that uncore_pmu_event_init() and snb_uncore_imc_event_init(), to 
pick a couple of Intel examples, contain a lot of the same logic to the 
ARM system PMU drivers you repeatedly request should be more verbose. 
Now, surely either perf tool already has some magic which somehow makes 
those routines "user-friendly", in which case there seems no reason that 
at least any generic event attribute stuff couldn't be applied to ARM 
PMUs as well; or if not then you could easily send a patch adding 
"helpful" printk()s to those drivers too and actively solicit the 
maintainer feedback you lament not having.

>>>>>> Anyway, I think this driver has bigger problems that need addressing.
>>>>>
>>>>> To me it represents yet another PMU driver submission - as the years go
>>>>> by - that is lacking in the user messaging area.  Which reminds me, can
>>>>> you take another look at applying this?:
>>>>
>>>> As I said before, I'm not going to take anything that logs above pr_debug
>>>> for things that are directly triggerable from userspace. Spin a version
>>>
>>> Why?  There are plenty of things that emit stuff into dmesg that are
>>> directly triggerable from userspace.  Is it because it upsets fuzzing
>>> tests?  How about those be run with a patched kernel that somehow
>>> mitigates the printing?
>>
>> [we've been over this before]
>> There are two camps that might find this information useful:
>>
>>    1. People writing userspace support for a new PMU using the
>>       perf_event_open syscall
>>
>>    2. People trying to use a tool which abstracts the PMU details to some
>>       degree (e.g. perf tool)
>>
>> Those in (1) can get by with pr_debug. Sure, they have to recompile, but
>> it's not like there are many people in this camp and they'll probably be
>> working with the PMU driver writer to some degree anyway and taking new
>> kernel drops.
> 
> No, please, that's a worse user experience than necessary.
> 
> FWIW, I see this type of person as e.g., a JIT developer - a
> compiler/toolchain person - who has decided to use h/w monitoring to
> help the JIT engine find hotspots.  The first place they should start
> is to start using the perf tool itself, experimenting with events and
> PMUs of interest.  When satisfied, they should clone the parameters
> the tool makes to the perf_event_open syscall in their JIT engine.  We
> should not be wasting their time forcing them to hack around in the
> kernel trying to debug perf driver semantics.
> 
>> Those in (2) may not have access to dmesg, absolutely should not be able
> 
> I don't think you're being realistic here: we're talking about people
> trying to improve performance: They would likely have kptr_restrict ==
> 0 (unrestricted), so why would they have dmesg_restrict set?  Btw, the
> rationale for dmesg_restrict was kernel pointer visibility [2], but now
> %Kp hashes addresses before printing them, so it's even less likely to
> be used.  Curious, where have you seen dmesg_restrict being set?
> 
>> to spam it (since this could hide other important messages), will probably
> 
> How will it hide other important messages?  Run a logging daemon?
> We're not talking about a lot of messages here: one line per perf
> invocation: see e.g. runs in [2].

Assuming you meant [3], that's a pretty trivial case which doesn't 
really illustrate the whole scope of the problem.

Just for you, I added prints in 4 places where event_init validation 
returns -EINVAL in my not-yet-upstream SMMUv2 PMU driver. Let's capture 
a few events on my Juno board to get some arbitrary cross-sections of 
system-wide I/O activity:

[root@...ce-channel-5 ~]# perf stat -e arm_smmu/cycles/ -e 
arm_smmu/access,tcefcfg=1/ -e arm_smmu/access,tcefcfg=1,smr_id=1/ -e 
arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ -e 
arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ find /usr > /dev/null

  Performance counter stats for 'system wide':

          729128494      arm_smmu/cycles/ 
               (12.08%)
          841301489      arm_smmu/cycles/ 
               (28.10%)
          834458758      arm_smmu/cycles/ 
               (23.40%)
          774373529      arm_smmu/cycles/ 
               (15.69%)
         1028501665      arm_smmu/cycles/ 
               (13.84%)
               5401      arm_smmu/access,tcefcfg=1/ 
                (27.11%)
                  0      arm_smmu/access,tcefcfg=1/ 
                (14.73%)
                  0      arm_smmu/access,tcefcfg=1/ 
                (23.27%)
                  0      arm_smmu/access,tcefcfg=1/ 
                (20.54%)
             220788      arm_smmu/access,tcefcfg=1/ 
                (17.37%)
                  0      arm_smmu/access,tcefcfg=1,smr_id=1/ 
                         (28.18%)
                  0      arm_smmu/access,tcefcfg=1,smr_id=1/ 
                         (24.10%)
                  0      arm_smmu/access,tcefcfg=1,smr_id=1/ 
                         (12.52%)
                  0      arm_smmu/access,tcefcfg=1,smr_id=1/ 
                         (16.17%)
                  0      arm_smmu/access,tcefcfg=1,smr_id=1/ 
                         (19.71%)
                  0      arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ 
                         (19.68%)
                  0      arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ 
                         (23.69%)
                  0      arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ 
                         (29.15%)
                  0      arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ 
                         (29.19%)
              12092      arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ 
                         (27.70%)
                  0      arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ 
                         (16.97%)
                  0      arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ 
                         (13.36%)
                  0      arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ 
                         (16.01%)
                  0      arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ 
                         (24.70%)
                  0      arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ 
                         (28.39%)

        2.315150449 seconds time elapsed


Wonderful, it worked OK. And yet in that brief time it spammed 
*sixty-one* lines to the kernel log:

[ 2096.220934] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.226893] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.232852] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.238798] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.244744] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.250690] event_source arm_smmu_4: Incompatible filtering mode
[ 2096.256641] event_source arm_smmu_2: Incompatible filtering mode
[ 2096.262594] event_source arm_smmu_0: Incompatible filtering mode
[ 2096.268546] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.274492] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.280437] event_source arm_smmu_4: Incompatible filtering mode
[ 2096.286381] event_source arm_smmu_2: Incompatible filtering mode
[ 2096.292326] event_source arm_smmu_0: Incompatible filtering mode
[ 2096.298271] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.304215] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.310164] event_source arm_smmu_4: Incompatible filtering mode
[ 2096.316109] event_source arm_smmu_2: Incompatible filtering mode
[ 2096.322053] event_source arm_smmu_0: Incompatible filtering mode
[ 2096.327997] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.333941] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.339887] event_source arm_smmu_3: Incompatible SMR value
[ 2096.345408] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.351361] event_source arm_smmu_4: Incompatible filtering mode
[ 2096.357313] event_source arm_smmu_2: Incompatible filtering mode
[ 2096.363263] event_source arm_smmu_0: Incompatible filtering mode
[ 2096.369214] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.375171] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.381124] event_source arm_smmu_4: Incompatible filtering mode
[ 2096.387078] event_source arm_smmu_2: Incompatible filtering mode
[ 2096.393029] event_source arm_smmu_0: Incompatible filtering mode
[ 2096.398984] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.404936] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.410890] event_source arm_smmu_4: Incompatible filtering mode
[ 2096.416840] event_source arm_smmu_4: Incompatible context bank index
[ 2096.423130] event_source arm_smmu_2: Incompatible filtering mode
[ 2096.429075] event_source arm_smmu_0: Incompatible filtering mode
[ 2096.435019] event_source arm_smmu_1: Incompatible context bank index
[ 2096.441308] event_source arm_smmu_3: Incompatible context bank index
[ 2096.447611] event_source arm_smmu_4: Incompatible filtering mode
[ 2096.453557] event_source arm_smmu_2: Incompatible filtering mode
[ 2096.459501] event_source arm_smmu_0: Incompatible filtering mode
[ 2096.465445] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.471390] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.477342] event_source arm_smmu_4: Incompatible filtering mode
[ 2096.483286] event_source arm_smmu_2: Incompatible SMR value
[ 2096.488800] event_source arm_smmu_0: Incompatible SMR value
[ 2096.494316] event_source arm_smmu_2: Incompatible filtering mode
[ 2096.500319] event_source arm_smmu_0: Incompatible filtering mode
[ 2096.571799] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.577749] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.583705] event_source arm_smmu_4: Incompatible SMR value
[ 2096.589221] event_source arm_smmu_2: Incompatible SMR value
[ 2096.594736] event_source arm_smmu_0: Incompatible SMR value
[ 2096.600256] event_source arm_smmu_1: Incompatible SMR value
[ 2096.605770] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.611718] event_source arm_smmu_4: Incompatible filtering mode
[ 2096.617663] event_source arm_smmu_2: Incompatible filtering mode
[ 2096.623607] event_source arm_smmu_0: Incompatible filtering mode
[ 2096.629550] event_source arm_smmu_1: Incompatible filtering mode
[ 2096.635494] event_source arm_smmu_3: Incompatible filtering mode
[ 2096.641443] event_source arm_smmu_4: Incompatible context bank index

(and in case it's not clear, that output is *continual* during the perf 
run; empirically, the runtime only needs to reach about 6 seconds or so 
for the dmesg ringbuffer to wrap so I have to fall back to journalctl to 
see what I missed)

Now how about we try counting those exact same events a slightly 
different way:

[root@...ce-channel-5 ~]# perf stat -e 
\{arm_smmu/cycles/,arm_smmu/access,tcefcfg=1/,arm_smmu/access,tcefcfg=1,smr_id=1/,arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/,arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/\} 
find /usr > /dev/null

  Performance counter stats for 'system wide':

      <not counted>      arm_smmu/cycles/ 

    <not supported>      arm_smmu/cycles/ 

    <not supported>      arm_smmu/cycles/ 

    <not supported>      arm_smmu/cycles/ 

    <not supported>      arm_smmu/cycles/ 

    <not supported>      arm_smmu/access,tcefcfg=1/ 

    <not supported>      arm_smmu/access,tcefcfg=1/ 

    <not supported>      arm_smmu/access,tcefcfg=1/ 

    <not supported>      arm_smmu/access,tcefcfg=1/ 

    <not supported>      arm_smmu/access,tcefcfg=1/ 

    <not supported>      arm_smmu/access,tcefcfg=1,smr_id=1/ 

    <not supported>      arm_smmu/access,tcefcfg=1,smr_id=1/ 

    <not supported>      arm_smmu/access,tcefcfg=1,smr_id=1/ 

    <not supported>      arm_smmu/access,tcefcfg=1,smr_id=1/ 

    <not supported>      arm_smmu/access,tcefcfg=1,smr_id=1/ 

    <not supported>      arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ 

    <not supported>      arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ 

    <not supported>      arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ 

    <not supported>      arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ 

    <not supported>      arm_smmu/tlb_alloc,tcefcfg=2,ndx=0/ 

    <not supported>      arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ 

    <not supported>      arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ 

    <not supported>      arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ 

    <not supported>      arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ 

    <not supported>      arm_smmu/tlb_alloc,tcefcfg=2,ndx=1/ 


        0.721310193 seconds time elapsed


Oh, that didn't work. Let's check dmesg to see why:

[ 2416.494951] event_source arm_smmu_3: Incompatible filtering mode
[ 2416.500933] event_source arm_smmu_3: Incompatible filtering mode
[ 2416.506958] event_source arm_smmu_3: Incompatible filtering mode
[ 2416.513276] event_source arm_smmu_3: Incompatible filtering mode


Well, it said the same thing continually when it worked correctly, so I 
guess it must have failed for some other reason. As the user I'm now not 
only confused but unknowingly heading towards the *wrong* conclusion 
thanks to those "helpful" messages. And that's not even contemplating 
the "what if multiple programs did this at the same time" case.

>> struggle to match an internal message from the PMU driver to their
>> invocation of the high-level tool and may well be in a multi-user
>> environment so will struggle to identify the messages that they are
>> responsible for.
> 
> Again, I think you're being unrealistic.  My experience - in
> multiple performance analysis roles - was that I was always the only
> person using the machine at the time, and can easily correlate perf
> invocations with dmesg output, particularly if I run 'dmesg -w &' prior
> to invoking perf.  In one of those roles, having to mess with the
> kernel was almost inconceivable - it literally 'just worked' for
> everything else.  I was lucky that I had prior kernel experience in
> order to debug the driver and be able find out how to invoke perf.
> 
>> What they actually want is for the perf tool to give
>> them more information, and dmesg is not the right channel for that, for
>> similar reasons.
> 
> We'd all like the perf tool to do things better, and dmesg is all we
> have for now, and now I'm sounding like I did 1 1/2 years ago.
> 
>>>> using pr_debug and I'll queue it.
>>>
>>> How about using a ratelimited dev_err variant?
>>
>> Nah, I don't want dmesg being parsed by users of perf tool. pr_debug should
>> be sufficient for perf tool developers working with a new PMU type.
> 
> OK the question was to the ratelimited part, but I think that even
> might be the default these days [4].
> 
> For reasons (different perceptions?) already mentioned above, I also
> don't agree that this has to do with just perf tool developers, and
> only when working with a new PMU type.  My main concern is new/future
> users to perf on Arm, working with any PMU type - new or old.  If there
> is a perf tool-side component to this driver, I don't see it.  Having
> said that, I think the owners of this and other PMU drivers should have
> a say in what type of experience they want for their users in this
> regard...is that fair?

As I've said before, a significant portion of what you want to improve 
involves generic perf_event properties which would already be much 
better validated in the core than by every driver individually, so the 
first straightforward step would be to improve the interface between 
drivers and perf core, such that the "hard" problem reduces to 
communicating from a single part of perf core to userspace. As it is, 
PMU drivers alone simply don't have enough context to know when an 
event_init "failure" is actually significant to the user or not, thus if 
they display user-visible messages directly then half the time the user 
will be thoroughly misled unless they are intimately familiar with how 
perf core grouping and event rotation work (see above), yet required 
knowledge of perf internals is exactly what you're arguing against!

Robin.

> 
> Thanks,
> 
> Kim
> 
> [1] https://patchwork.kernel.org/patch/9907463/
> [2] https://lwn.net/Articles/414813/
> [3] https://lkml.org/lkml/2017/11/21/385
> [4] https://lwn.net/Articles/693010/
> 
> _______________________________________________
> linux-arm-kernel mailing list
> linux-arm-kernel@...ts.infradead.org
> http://lists.infradead.org/mailman/listinfo/linux-arm-kernel
> 

Powered by blists - more mailing lists