[Piglit] [PATCH v2 1/4] framework/dmesg: Adds a new module for dmesg
Ilia Mirkin
imirkin at alum.mit.edu
Sat Feb 1 17:42:29 PST 2014
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
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 :)
>
>> Of course the pathological case of the ring being filled with
>> identical lines would be annoying.
>>
>> At the very least, change your .index() to .rindex()?
>
> what's rindex()? It's not in the documentation for list in either python2.7 or
> 3.3, and when I use it in the interpreter I get an exception.
Oh. I assumed it existed without checking. Looks like it exists on str
but not on list... Sad. But basically you should look for the last
instance of the line rather than the first.
>
>>
>> >> > + except ValueError:
>> >> > + self._new_messages = dmesg
>> >> > +
>> >> > + # Update the last message with the last element of the dmesg
>> >> > snapshot + self._last_message = dmesg[-1]
>> >>
>> >> dmesg could also be empty (e.g. if I ran dmesg -c first)... so this
>> >> would trigger an IndexError.
>> >
>> > Right, fixed.
>> >
>> >> > +
>> >> > +
>> >> > +class DummyDmesg(object):
>> >> > + """ An dummy class for dmesg on non unix-like systems
>> >> > +
>> >> > + This implements a dummy version of the PosixDmesg, and can be used
>> >> > anytime + it is not desirable to actually read dmesg, such as
>> >> > non-posix systems, or + when the contents of dmesg don't matter.
>> >> > +
>> >> > + """
>> >> > + DMESG_COMMAND = []
>> >> > +
>> >> > + def __init__(self):
>> >> > + pass
>> >> > +
>> >> > + def update_dmesg(self):
>> >> > + """ Dummy version of update_dmesg """
>> >> > + pass
>> >> > +
>> >> > + def update_result(self, result):
>> >> > + """ Dummy version of update_result """
>> >> > + return result
>> >> > +
>> >> > +
>> >> > +def get_dmesg(not_dummy=True):
>> >> > + """ Return a Dmesg type instance
>> >> > +
>> >> > + Normally this does a system check, and returns the type that
>> >> > proper
>> >> > for + your system. However, if Dummy is True then it will always
>> >> > return a + DummyDmesg instance.
>> >> > +
>> >> > + """
>> >> > + if os.name == "posix" and not_dummy:
>> >> > + return PosixDmesg()
>> >> > + return DummyDmesg()
>> >> > --
>> >> > 1.8.5.3
>> >> >
>> >> > _______________________________________________
>> >> > Piglit mailing list
>> >> > Piglit at lists.freedesktop.org
>> >> > http://lists.freedesktop.org/mailman/listinfo/piglit
More information about the Piglit
mailing list