Date: Mon, 15 Jun 2009 12:45:16 +1000 (EST) From: Bruce Evans <brde@optusnet.com.au> To: Sam Leffler <sam@FreeBSD.org> Cc: svn-src-head@FreeBSD.org, svn-src-all@FreeBSD.org, src-committers@FreeBSD.org, Ed Schouten <ed@FreeBSD.org>, Bruce Evans <brde@optusnet.com.au> Subject: Re: svn commit: r194204 - in head/sys: amd64/conf i386/conf Message-ID: <20090615114142.B775@besplex.bde.org> In-Reply-To: <4A359AA6.7010101@freebsd.org> References: <200906141801.n5EI1Zti056239@svn.freebsd.org> <4A356A0F.3050800@freebsd.org> <20090615075134.K24645@delplex.bde.org> <4A359AA6.7010101@freebsd.org>
next in thread | previous in thread | raw e-mail | index | archive | help
On Sun, 14 Jun 2009, Sam Leffler wrote:
> Bruce Evans wrote:
>> On Sun, 14 Jun 2009, Sam Leffler wrote:
>>
>>>> Log:
>>>> Enable PRINTF_BUFR_SIZE on i386 and amd64 by default.
>>>>
>>>> In the past there have been some reports of PRINTF_BUFR_SIZE not
>>>> functioning correctly. Instead of having garbled console messages, we
>>>> should just see whether the issues are still there and analyze them.
>>>
>>> When I suggested enabling this by default for SMP configurations I was
>>> reminded it wasn't enabled because of potential stack overflow.
>>
>> Stack overflow shouldn't be a problem, since printf shouldn't be called
>> recursively.
>
> You don't need recursion to overflow the stack.
You should need it, since it the stack is going to overflow from another
128-512 bytes of unnecessary stuff on it, then it is too close to
overflowing with 128-512 bytes of necessary stuff on it.
> I'd love to see someone
> properly lock printf/console output instead of kludges like PRINTF_BUFR_SIZE.
Almost done (for FreeBSD-~5.2): non-production version with lots of debugging
cruft:
% --- subr_prf.c~~ Sun Jun 20 14:40:46 2004
% +++ subr_prf.c Mon Jun 15 11:39:29 2009
% @@ -468,4 +468,39 @@
% }
%
% +static int printf_lockcount;
% +static int printf_timeout = 1000;
% +
% +static void
% +printf_lock(void)
% +{
% + struct timeval tv, tv1;
% + static int t;
% + int timeout;
% +
% + if (db_active)
% + return;
% + microuptime(&tv);
% + timeout = printf_timeout;
% + do {
% + if (atomic_cmpset_acq_int(&printf_lockcount, 0, 1))
% + return;
% + breakpoint();
% + DELAY(1000);
% + } while (--timeout != 0);
% + microuptime(&tv1);
% + t = (tv1.tv_sec - tv.tv_sec) * 1000000 + tv1.tv_usec - tv.tv_usec;
% + breakpoint();
% + atomic_add_acq_int(&printf_lockcount, 1);
% +}
% +
% +static void
% +printf_unlock(void)
% +{
% +
% + if (db_active)
% + return;
% + atomic_add_rel_int(&printf_lockcount, -1);
% +}
% +
% /*
% * Scaled down version of printf(3).
% @@ -523,10 +558,13 @@
% radix = 10;
%
% + printf_lock();
% for (;;) {
% padc = ' ';
% width = 0;
% while ((ch = (u_char)*fmt++) != '%') {
% - if (ch == '\0')
% + if (ch == '\0') {
% + printf_unlock();
% return (retval);
% + }
% PCHAR(ch);
% }
% @@ -799,4 +837,5 @@
% }
% #undef PCHAR
% + breakpoint();
% }
%
The locking is centralized in kvprintf() like I said to, but this is
excessive since kvprintf() is used even for strings. It will have
to be applied only to printf() and vprintf() and maybe another function
where the pca.bufr initializations are.
The debugging code (and the original version without any debugging code)
shows very interesting behaviour (bugs) for ddb.
- ddb calls kvprintf() recursively! Only 2 levels I think.
- when ddb calls kvprintf() recursively, it sometimes violates its own
rules and calls via printf() instead of via db_printf().
- the above 2 bugs combined with implementation details give extreme
slowness (< 1 char per second) when they occur. I have programmed the
delay larger than necessary (1 second) so as to make such bugs more
obvious. They are even obvious with a 50 ms delay due to the
implementation details. These are:
+ db_printf() is essentially kvprintf() with db_putchar() as the
per-char output routine
+ db_putchar() calls back to kvprintf() in some (unusual) cases. (In
usual cases it calls cnputc() directly.) This gives
the recursion. It also gives inefficiency, but no
one notices unless there is a delay. With string
printfs() also affected, and most strings being 1
character long (possibly preformatted by a string
printf(), even a delay of 50 ms is very noticable.
+ When ddb calls back to kvprintf(), it intentionally breaks its own
rule of never calling printf() directly. The PRINT_BUFR stuff
doesn't expect this.
+ The unusual case where db_putchar() calls back to kvprintf() is the
usual case for interactive debugger entry under ~5.2, so I saw it
immediately. All versions of debugger entry erroneously print stuff
before being fully entered. Debugger("") in ~5.2 uses db_printf()
and this gives the recursion, etc., since db_putchar() is "smart"
and knows that calls to db_printf() in non-debugger mode are errors,
so it switches to printf(). kdb_enter() in -current calls printf()
and thus misses benefits from the special handling in db_printf().
+ The unusual case where db_putchar() calls back to kvprintf() is the
usual case when someone sets the "debug.ddb_use_printf" sysctl to 1.
At least 4 levels of recursion into kvprintf() are possible without
anything else being wrong -- 1 for a normal call, 1 for a panic, plus
2 as above for db_printf().
Bruce
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20090615114142.B775>