Skip site navigation (1)Skip section navigation (2)
Date:      Fri, 17 Feb 2012 09:24:54 -0800
From:      Marcel Moolenaar <marcel@xcllnt.net>
To:        Pawel Jakub Dawidek <pjd@FreeBSD.org>
Cc:        marcel@FreeBSD.org, Eitan Adler <eadler@FreeBSD.org>, svn-src-all@FreeBSD.org, "Kenneth D. Merry" <ken@FreeBSD.org>, Andriy Gapon <avg@FreeBSD.org>, src-committers@FreeBSD.org, Bruce Evans <brde@optusnet.com.au>, svn-src-head@FreeBSD.org, Julian Elischer <julian@FreeBSD.org>
Subject:   Re: svn commit: r231814 - in head/sys: kern sys
Message-ID:  <1AC67C3A-F6D5-419F-BD15-26AACF6BA567@xcllnt.net>
In-Reply-To: <20120217085840.GC1358@garage.freebsd.pl>
References:  <201202160511.q1G5BZNk099785@svn.freebsd.org> <20120216181210.K1423@besplex.bde.org> <4F3CC40D.4000307@freebsd.org> <4F3CC5C4.7020501@FreeBSD.org> <4F3CC8A5.3030107@FreeBSD.org> <20120216174758.GA64180@nargothrond.kdm.org> <20120217053341.R1256@besplex.bde.org> <20120217000846.GA7641@nargothrond.kdm.org> <4F3D9D03.6020507@FreeBSD.org> <9CB7ECE8-FF10-43BE-9EBD-16953BE3B193@xcllnt.net> <20120217085840.GC1358@garage.freebsd.pl>

next in thread | previous in thread | raw e-mail | index | archive | help

On Feb 17, 2012, at 12:58 AM, Pawel Jakub Dawidek wrote:

*snip*
>> I think we should lift above the immediate problem and allow for
>> single- and multi-line messages that are atomically appended to
>> the message buffer. Console output and propagation of messages
>> outside of the kernel should all come out of the message buffer
>> and preserving the atomicity of the messages.
>> 
>> The message buffer does not have to be a chunk of memory that
>> we circularly scribble to. It can be a per-cpu linked list of
>> messages even.
*snip*
> 
> I agree with everything except for per-CPU buffers. I understand the
> need for using printf in low-level code and it indeed complicates things.
> The reason I don't like the idea of per-CPU buffers is that locking
> would allow me to implement atomicity across multiple printfs.
> For example I often use macros like this:
> 
> #define	G_MIRROR_DEBUG(lvl, ...)	do {				\
> 	if (g_mirror_debug >= (lvl)) {					\
> 		printf("GEOM_MIRROR");					\
> 		if (g_mirror_debug > 0)					\
> 			printf("[%u]", lvl);				\
> 		printf(": ");						\
> 		printf(__VA_ARGS__);					\
> 		printf("\n");						\
> 	}								\
> } while (0)
> 
> And I'd like all the printfs to be committed as one message without
> using some additional buffer first and then single printf.
> With some kind of printf-lock we could use recursive locking to achieve
> this. In your proposal I may run each printf on different CPU.
> I could eventually use sched_pin() around all printfs, I guess.
> This still doesn't cover the case when I'm preempted between my printfs,
> so maybe I need critical section there? I don't expect printf should be
> fast, so it might be ok.

I'm sure there's an elegant solution somewhere to be found.

In fact, I'm actually thinking broader still: to fundamentally
replace printf with logging, similar to syslog and define
printf as a macro or wrapper for logging (with some fixed priority
and/or facility).

The most important aspect of this is that we can better control
the verbosity of the boot. The least verbose boot would only
print the absolutely required messages (read: legaleze). At the
most verbose boot you get whatever log or print exists in the
kernel in the code that gets executed. There's many levels
in between. The facility allows us to crank up verbosity for
components or drivers only and helps us to focus on the area
of interest. I.e. if there's a driver that won't attach, it's
really nice to have that driver as verbose as it gets without
also having to sift through megabytes of unrelated noise.

Debug output is no different from "very verbose" output and
biggest problem we have is to define a good set of standard
priorities that people can use.

With the above, I see no problem cuddling up to sbuf(9) and
use sbuf to collect fragments and or multiple lines and use
it to atomically "print" the message. A simple transactional
model should suffice, as in:
	lt = log_begin(sbuf, priority, facility);
	log(lt, "foo");
	log(lt, "\nbar\n");
		:
	log(lt, "baz");
	log_end(lt);

This eliminates any need for one-off macros to do this stuff,
like the one you typically use.

Oh, and it would be nice to have a kernel configuration that
controls which priority levels get compiled in, so that you
can easily construct a kernel without tons of high verbosity
log messages when you don't want them.

-- 
Marcel Moolenaar
marcel@xcllnt.net





Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?1AC67C3A-F6D5-419F-BD15-26AACF6BA567>