From owner-svn-src-head@FreeBSD.ORG Mon Jun 15 02:45:21 2009 Return-Path: Delivered-To: svn-src-head@FreeBSD.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 1CE0B106564A; Mon, 15 Jun 2009 02:45:21 +0000 (UTC) (envelope-from brde@optusnet.com.au) Received: from mail03.syd.optusnet.com.au (mail03.syd.optusnet.com.au [211.29.132.184]) by mx1.freebsd.org (Postfix) with ESMTP id A81AC8FC17; Mon, 15 Jun 2009 02:45:20 +0000 (UTC) (envelope-from brde@optusnet.com.au) Received: from besplex.bde.org (c122-106-159-184.carlnfd1.nsw.optusnet.com.au [122.106.159.184]) by mail03.syd.optusnet.com.au (8.13.1/8.13.1) with ESMTP id n5F2jG6X002969 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO); Mon, 15 Jun 2009 12:45:18 +1000 Date: Mon, 15 Jun 2009 12:45:16 +1000 (EST) From: Bruce Evans X-X-Sender: bde@besplex.bde.org To: Sam Leffler In-Reply-To: <4A359AA6.7010101@freebsd.org> Message-ID: <20090615114142.B775@besplex.bde.org> References: <200906141801.n5EI1Zti056239@svn.freebsd.org> <4A356A0F.3050800@freebsd.org> <20090615075134.K24645@delplex.bde.org> <4A359AA6.7010101@freebsd.org> MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII; format=flowed Cc: svn-src-head@FreeBSD.org, svn-src-all@FreeBSD.org, src-committers@FreeBSD.org, Ed Schouten , Bruce Evans Subject: Re: svn commit: r194204 - in head/sys: amd64/conf i386/conf X-BeenThere: svn-src-head@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: SVN commit messages for the src tree for head/-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 15 Jun 2009 02:45:21 -0000 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