[Piglit] [PATCH v2 1/4] framework/dmesg: Adds a new module for dmesg
Ilia Mirkin
imirkin at alum.mit.edu
Sun Feb 2 11:34:10 PST 2014
On Sat, Feb 1, 2014 at 10:12 PM, Dylan Baker <baker.dylan.c at gmail.com> wrote:
> On Saturday, February 01, 2014 08:42:29 PM Ilia Mirkin wrote:
>> On Sat, Feb 1, 2014 at 8:03 PM, Dylan Baker <baker.dylan.c at gmail.com> wrote:
>> > On Saturday, February 01, 2014 06:06:21 PM Ilia Mirkin wrote:
>> >> On Sat, Feb 1, 2014 at 5:13 PM, Dylan Baker <baker.dylan.c at gmail.com>
> wrote:
>> >> > On Saturday, February 01, 2014 08:44:07 AM Ilia Mirkin wrote:
>> >> >> On Sat, Feb 1, 2014 at 3:30 AM, Dylan Baker <baker.dylan.c at gmail.com>
>> >
>> > wrote:
>> >> >> > This modules implements two classes and a helper function. The two
>> >> >> > classes are both dmesg wrapper classes, one, PosixDmesg is used on
>> >> >> > posix
>> >> >> > systems when requested to actually do checks on dmesg. The second
>> >> >> > class,
>> >> >> > DummyDmesg, is used to reduce code complexity by providing dummy
>> >> >> > versions of the methods in PosixDmesg. This means that we don't need
>> >> >> > separate code paths for Posix systems wanting to check dmesg, Posix
>> >> >> > systems not wanting to check dmesg, and non-posix systems which lack
>> >> >> > dmesg.
>> >> >> >
>> >> >> > Beyond reducing complexity this module also gives better isolation,
>> >> >> > dmesg is only used in Test.execute(), no where else. Additional
>> >> >> > classes
>> >> >> > don't need to worry about dmesg that way, it's just available.
>> >> >> >
>> >> >> > V2: - Remove unnecessary assert from PosixDmesg.update_result()
>> >> >> >
>> >> >> > - simplify replace helper in PoixDmesg.update_result()
>> >> >> > - replace try/except with if check
>> >> >> > - Change PosixDmesg.update_dmesg() to work even if dmesg 'wraps'
>> >> >> >
>> >> >> > Signed-off-by: Dylan Baker <baker.dylan.c at gmail.com>
>> >> >> > ---
>> >> >> >
>> >> >> > framework/dmesg.py | 147
>> >> >> > +++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file
>> >> >> > changed,
>> >> >> > 147 insertions(+)
>> >> >> > create mode 100644 framework/dmesg.py
>> >> >> >
>> >> >> > diff --git a/framework/dmesg.py b/framework/dmesg.py
>> >> >> > new file mode 100644
>> >> >> > index 0000000..65c3a15
>> >> >> > --- /dev/null
>> >> >> > +++ b/framework/dmesg.py
>> >> >> > @@ -0,0 +1,147 @@
>> >> >> > +# Copyright (c) 2013-2014 Intel Corporation
>> >> >> > +#
>> >> >> > +# Permission is hereby granted, free of charge, to any person
>> >> >> > obtaining a
>> >> >> > +# copy of this software and associated documentation files (the
>> >> >> > "Software"), +# to deal in the Software without restriction,
>> >> >> > including
>> >> >> > without limitation +# the rights to use, copy, modify, merge,
>> >> >> > publish,
>> >> >> > distribute, sublicense, +# and/or sell copies of the Software, and
>> >> >> > to
>> >> >> > permit persons to whom the +# Software is furnished to do so,
>> >> >> > subject
>> >> >> > to
>> >> >> > the following conditions: +#
>> >> >> > +# The above copyright notice and this permission notice (including
>> >> >> > the
>> >> >> > next +# paragraph) shall be included in all copies or substantial
>> >> >> > portions of the +# Software.
>> >> >> > +#
>> >> >> > +# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
>> >> >> > EXPRESS
>> >> >> > OR +# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
>> >> >> > MERCHANTABILITY, +# FITNESS FOR A PARTICULAR PURPOSE AND
>> >> >> > NONINFRINGEMENT.
>> >> >> >
>> >> >> > IN NO EVENT SHALL +# THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR
>> >> >> > ANY
>> >> >> >
>> >> >> > CLAIM, DAMAGES OR OTHER +# LIABILITY, WHETHER IN AN ACTION OF
>> >> >> > CONTRACT,
>> >> >> > TORT OR OTHERWISE, ARISING +# FROM, OUT OF OR IN CONNECTION WITH THE
>> >> >> > SOFTWARE OR THE USE OR OTHER DEALINGS +# IN THE SOFTWARE.
>> >> >> > +
>> >> >> > +""" Module implementing classes for reading posix dmesg """
>> >> >> > +
>> >> >> > +import os
>> >> >> > +import subprocess
>> >> >> > +
>> >> >> > +__all__ = ['PosixDmesg', 'DummyDmesg', 'get_dmesg']
>> >> >> > +
>> >> >> > +
>> >> >> > +class PosixDmesg(object):
>> >> >> > + """ Read dmesg on posix systems
>> >> >> > +
>> >> >> > + This reads the dmesg ring buffer, stores the contents of the
>> >> >> > buffer,
>> >> >> > and + then compares it whenever called, returning the difference
>> >> >> > between the + calls.
>> >> >> > +
>> >> >> > + This class is not thread-safe, but with the caveat that the
>> >> >> > test
>> >> >> > reporting + dmesg problems might not be the test that generated
>> >> >> > them.
>> >> >> > dmesg reporting + can only be considered authoritative when
>> >> >> > running
>> >> >> > non-concurrently. +
>> >> >> > + """
>> >> >> > + DMESG_COMMAND = ['dmesg']
>> >> >> > +
>> >> >> > + def __init__(self):
>> >> >> > + """ Create a dmesg instance """
>> >> >> > + self._last_message = None
>> >> >> > + self._new_messages = []
>> >> >> > +
>> >> >> > + # Populate self.dmesg initially, otherwise the first test
>> >> >> > will
>> >> >> > always + # be full of dmesg crud.
>> >> >> > + self.update_dmesg()
>> >> >> > +
>> >> >> > + def update_result(self, result):
>> >> >> > + """ Takes a TestResult object and updates it with dmesg
>> >> >> > statuses
>> >> >> > +
>> >> >> > + If dmesg is enabled, and if dmesg has been updated, then
>> >> >> > replace
>> >> >> > pass + with dmesg-warn and warn and fail with dmesg-fail. If
>> >> >> > dmesg
>> >> >> > has not + been updated, it will return the original result
>> >> >> > passed
>> >> >> > in. +
>> >> >> > + Arguments:
>> >> >> > + result -- A TestResult instance
>> >> >> > +
>> >> >> > + """
>> >> >> > +
>> >> >> > + def replace(res):
>> >> >> > + """ helper to replace statuses with the new dmesg
>> >> >> > status
>> >> >> > +
>> >> >> > + Replaces pass with dmesg-warn, and warn and fail with
>> >> >> > dmesg-fail, + otherwise returns the input
>> >> >> > +
>> >> >> > + """
>> >> >> > + return {"pass": "dmesg-warn",
>> >> >> > + "warn": "dmesg-fail",
>> >> >> > + "fail": "dmesg-fail"}.get(res, res)
>> >> >> > +
>> >> >> > + # Get a new snapshot of dmesg
>> >> >> > + self.update_dmesg()
>> >> >> > +
>> >> >> > + # if update_dmesg() found new entries replace the results
>> >> >> > of
>> >> >> > the
>> >> >> > test + # and subtests
>> >> >> > + if self._new_messages:
>> >> >> > + result['result'] = replace(result['result'])
>> >> >> > +
>> >> >> > + # Replace any subtests
>> >> >> > + if 'subtest' in result:
>> >> >> > + for key, value in result['subtest'].iteritems():
>> >> >> > + result['subtest'][key] = replace(value)
>> >> >> > +
>> >> >> > + # Add the dmesg values to the result
>> >> >> > + result['dmesg'] = self._new_messages
>> >> >> > +
>> >> >> > + return result
>> >> >> > +
>> >> >> > + def update_dmesg(self):
>> >> >> > + """ Call dmesg using subprocess.check_output
>> >> >> > +
>> >> >> > + Get the contents of dmesg, then calculate new messages,
>> >> >> > finally
>> >> >> > set + self.dmesg equal to the just read contents of dmesg.
>> >> >> > +
>> >> >> > + """
>> >> >> > + dmesg =
>> >> >> > subprocess.check_output(self.DMESG_COMMAND).strip().splitlines() +
>> >> >> > + # Find all new entries, do this by slicing the list of
>> >> >> > dmesg
>> >> >> > to
>> >> >> > only + # returns elements after the last element stored. If
>> >> >> > there
>> >> >> > are not + # matches a value error is raised, that means all
>> >> >> > of
>> >> >> > dmesg is new + try:
>> >> >> > + self._new_messages =
>> >> >> > dmesg[dmesg.index(self._last_message)
>> >> >> > +
>> >> >> > 1:]
>> >> >>
>> >> >> This will very mildly fail if you've rotated the ring buffer enough to
>> >> >> leave just part of the last message there, but that's unlikely enough
>> >> >> (and annoying enough to fix) that it's OK :)
>> >> >
>> >> > Maybe I'm wrong, but looking at the output of the dmesg command after
>> >> > running this in zsh:
>> >> > i=1
>> >> > while ((1)) { echo "loop test ${i}; let i++ }
>> >> > It looks like the dmesg command always presents a linear view, the
>> >> > sorted
>> >> > by time not by where in the ring they are. It also appears to trim
>> >> > partial byte strings only presenting whole lines.
>> >>
>> >> Hm, cool. It does seem like dmesg protects against this. I've
>> >> definitely seen partial lines somewhere though... perhaps I'm
>> >> misremembering though.
>> >>
>> >> >> However if you don't have timestamps enabled, then this won't quite
>> >> >> work either -- a lot of messages end up looking rather similar.
>> >> >> Especially if you're running, e.g., piglit, which triggers the same
>> >> >> message on 100 diff tests. I think the approach of storing the old
>> >> >> dmesg and then attempting to line them up would almost always produce
>> >> >> an accurate result... But perhaps that's too expensive and not worth
>> >> >> it? Dunno.
>> >> >
>> >> > I couldn't find an option in the kernelconfig to turn off timestamps,
>> >> > the
>> >> > only option I could find was an option to dmesg itself. Since we
>> >> > control
>> >> > what the dmesg command is maybe the best solution is to just leave a
>> >> > comment that says turning off time stamps is bad?
>> >>
>> >> Try building without CONFIG_PRINTK_TIME. Or boot with printk_time=0.
>> >
>> > Well, I've never seen a stock kernel without those options, and maybe in
>> > this case it's best to just say we can't protect every user from their
>> > own folly.
>> >
>> > Although maybe the right solution is to do some sort of check up front to
>> > see if a system has timestamps and bail out if dmesg is requested and
>> > there are no timestamps.
>> >
>> >> Also, I don't think other OS's have this (e.g. FreeBSD -- although I
>> >> last looked at FreeBSD many many many years ago).
>> >
>> > I checked my local BSD machine and FreeBSD 8 at least does not have
>> > timestamps in their dmesg implementation, Not sure about 9 and 10. I'm
>> > not horribly worried about the BSDs, since I don't know that anyone runs
>> > piglit on BSD, but if that carries over into Darwin/OSX that could be
>> > problematic.
>> >
>> > ONTOH, the current implementation assumes timestamps in the default
>> > format, so>
>> > I don't know if it's that big of a deal. :shrug:
>> >> > The slicing approach I'm using in v2 seems pretty good because of
>> >> > simplicity, and since piglit is already running in serial mode with
>> >> > dmesg
>> >> > checking enabled it's gonna be slow, I think even if there is the
>> >> > timestamps corner case the performance might be worth it. Dunno either.
>> >>
>> >> Yeah, the lining up can be a bit of a pain. I was thinking of assuming
>> >> that there existed an offset x, and doing like
>> >>
>> >> for x in xrange(len(dmesg)):
>> >> for a,b in izip(dmesg[x:], old_dmesg):
>> >> if a != b:
>> >> break
>> >>
>> >> else
>> >>
>> >> we have a match
>> >>
>> >> Since x would, on average, be no more than 50, it wouldn't be _so_ bad
>> >> (and when things didn't line up, it'd bail out pretty quickly).
>> >
>> > So, I have ~7000 lines in my dmesg right now, granted I put a lot of them
>> > there intentionally with my little foolery, but I'm concerned that on a
>> > preproduction system or with drm.debug=0x6 (be really chatty) that we
>> > could be calling izip on two 7000 element lists 16000 times...
>>
>> Not sure where the 16000 is coming from, but yes, potentially this
>
> 16283, the number of tests in all.py as of this moment.
Oh, I understand what you're saying now.
>
>> would take n^2 time. However in the 99.9999734% case, it would be more
>> like n time since the lines would immediately, or very quickly, not
>> match up. Especially if you have timestamps enabled :)
>
> Or not, since the dmesg command sorts things linearly by time stamp if dmesg
> isn't full, but getting close, we would end up iterating over thousands if
> identical entries over and over until we actually wrap, if we wrap.
My main point is that the code I proposed a few e-mails ago should, in
the _vast_ majority of situations, be only a constant factor slower
than doing dmesg.index(last_line). izip is ~free (it doesn't actually
copy anything), so the loss in efficiency comes from either things not
being lined up with x == 0 (which, unless you have the pathological
case of lines being mostly identical, should be minimal, since it
should break out of the comparison loop early on), and from the fact
that python code is slower than built-in logic (i.e. implementing
list.index in python would just be slower than using the built-in
list.index).
>
> I'll do a some more testing and thinking about it, and get back to you on
> Monday.
OK. Well, especially since the old code didn't deal with the
no-timestamp case particularly well either, this seems like less of a
big deal -- perhaps the fix for looking for the last line from the end
rather than from the beginning would be sufficient. But I do come
across dmesg's without timestamps every so often, and unless there's a
flaw in my reasoning above, it seems pretty easy to do it "right" (or
at least as right as it's going get).
-ilia
More information about the Piglit
mailing list