From owner-svn-src-projects@FreeBSD.ORG Sun May 4 09:26:38 2014 Return-Path: Delivered-To: svn-src-projects@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id 8CF1052A; Sun, 4 May 2014 09:26:38 +0000 (UTC) Received: from mail108.syd.optusnet.com.au (mail108.syd.optusnet.com.au [211.29.132.59]) by mx1.freebsd.org (Postfix) with ESMTP id 2208611E8; Sun, 4 May 2014 09:26:37 +0000 (UTC) Received: from c122-106-147-133.carlnfd1.nsw.optusnet.com.au (c122-106-147-133.carlnfd1.nsw.optusnet.com.au [122.106.147.133]) by mail108.syd.optusnet.com.au (Postfix) with ESMTPS id 07C741A4244; Sun, 4 May 2014 19:26:27 +1000 (EST) Date: Sun, 4 May 2014 19:25:06 +1000 (EST) From: Bruce Evans X-X-Sender: bde@besplex.bde.org To: Andrew Turner Subject: Re: svn commit: r265268 - projects/arm64/sys/arm64/arm64 In-Reply-To: <201405031527.s43FRUTg019278@svn.freebsd.org> Message-ID: <20140504182755.K1388@besplex.bde.org> References: <201405031527.s43FRUTg019278@svn.freebsd.org> MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII; format=flowed X-Optus-CM-Score: 0 X-Optus-CM-Analysis: v=2.1 cv=eojmkOZX c=1 sm=1 tr=0 a=7NqvjVvQucbO2RlWB8PEog==:117 a=PO7r1zJSAAAA:8 a=IFCUVFEhucQA:10 a=kj9zAlcOel0A:10 a=JzwRw_2MAAAA:8 a=clgEMp62zpTS0TH2SX4A:9 a=FHSuXwAb4DHk2-_3:21 a=SChrp_th2E8iCYHz:21 a=CjuIK1q_8ugA:10 Cc: svn-src-projects@freebsd.org, src-committers@freebsd.org X-BeenThere: svn-src-projects@freebsd.org X-Mailman-Version: 2.1.17 Precedence: list List-Id: "SVN commit messages for the src " projects" tree" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 04 May 2014 09:26:38 -0000 On Sat, 3 May 2014, Andrew Turner wrote: > Log: > Replace panic with printf in spinlock_{enter,exit} as panic makes use of > spinlocks. printf has been broken to use spinlocks too. It used to be careful to use atomic operations to avoid locking. Most console drivers are broken too. Some serial ones avoid locking in debugger mode only. > Modified: projects/arm64/sys/arm64/arm64/machdep.c > ============================================================================== > --- projects/arm64/sys/arm64/arm64/machdep.c Sat May 3 15:03:47 2014 (r265267) > +++ projects/arm64/sys/arm64/arm64/machdep.c Sat May 3 15:27:30 2014 (r265268) > @@ -221,14 +221,14 @@ void > spinlock_enter(void) > { > > - panic("spinlock_enter"); > + printf("spinlock_enter\n"); > } > > void > spinlock_exit(void) > { > > - panic("spinlock_exit"); > + printf("spinlock_exit\n"); > } I think panic() often blows away locking (that is another type of brokenness), but that isn't going to work for the above. Any spinlocking in a printf in panic is just going to call printf recursively. The first locking bug in printf is somewhere near: subr_msgbuf.c: % /* % * Append a character to a message buffer. % */ % void % msgbuf_addchar(struct msgbuf *mbp, int c) % { % mtx_lock_spin(&mbp->msg_lock); % % msgbuf_do_addchar(mbp, &mbp->msg_wseq, c); % % mtx_unlock_spin(&mbp->msg_lock); % } This has about the same density of style bugs as locking bugs. The mutex here is a non-recursive spinlock, so any printf in its acquiry will panic recursively if INVARIANTS is enabled. You really shouldn't call printf from low-level locking code, but for debugging printf should work in such contexts. Note that it must work when called by debuggers for single-stepping through such contexts, so console drivers must work in such contexts and whatever makes that work needs only relatively trivial changes to work generally. Some bugs are avoided by not writing to the message buffer in some contexts, but writing atomically to the message buffer is relatively trivial. The non-broken version of this (from FreeBSD-5.1) is: % /* % * Append a character to a message buffer. This function can be % * considered fully reentrant so long as the number of concurrent % * callers is less than the size of the buffer. % * However, the message buffer is only guaranteed to be consistent % * for reading when there are no callers in this function. % */ % void % msgbuf_addchar(struct msgbuf *mbp, int c) % { % u_int new_seq, pos, seq; % % do { % seq = mbp->msg_wseq; % new_seq = MSGBUF_SEQNORM(mbp, seq + 1); % } while (atomic_cmpset_rel_int(&mbp->msg_wseq, seq, new_seq) == 0); % pos = MSGBUF_SEQ_TO_POS(mbp, seq); % atomic_add_int(&mbp->msg_cksum, (u_int)(u_char)c - % (u_int)(u_char)mbp->msg_ptr[pos]); % mbp->msg_ptr[pos] = c; % } I use similar methods to unbreak some versions syscons a little. The unbreakage detects some cases of deadlock for normal locking (these occur mainly for buggy recursion like printf from low levels), and when they occur the handling is not to panic recursively but is to splat the message together with some extra debugging info onto the vga frame buffer using atomic ops like the above, and also to splat the message into a local message buffer. The local message buffer is replayed as normal output later if possible. The first locking bug in console drivers is somewhere near: % void % cnputs(char *p) % { % int c; % int unlock_reqd = 0; % % if (use_cnputs_mtx) { % mtx_lock_spin(&cnputs_mtx); % unlock_reqd = 1; % } % % while ((c = *p++) != '\0') % cnputc(c); % % if (unlock_reqd) % mtx_unlock_spin(&cnputs_mtx); % } The mutex here is a non-recursive spinlock, so any printf that calls cnputs in its acquiry will panic recursively if INVARIANTS is enabled, as above. This bug is smaller than the above, since cnputs is not use for all printfs. It is used unconditionally mainly if the PRINTF_BUFR_SIZE bug is configured. This is now the default in GENERIC :-(. printf buffering is turned off in some low-level contexts including debugger contexts, but I don't see anything to do that for a generic printf when PRINTF_BUFR_SIZE is configured. PRINTF_BUFR_SIZE is broken as designed, since you just can't have serialization of printfs for printfs from lower levels. Serialization of a printf from spinlock_enter asks for either blocking spinlock_enter if the serialization buffer is locked by another CPU, or deadlock if the serialization buffer is locked by the same CPU. Here is an old version of my printf serialization patches. See the accompanying mail in 2009 for more details % Index: subr_prf.c % =================================================================== % RCS file: /home/ncvs/src/sys/kern/subr_prf.c,v % retrieving revision 1.130.2.1 % diff -u -2 -r1.130.2.1 subr_prf.c % --- subr_prf.c 21 Jan 2009 00:26:45 -0000 1.130.2.1 % +++ subr_prf.c 15 Jun 2009 05:32:03 -0000 % @@ -112,4 +112,27 @@ % &always_console_output, 0, "Always output to console despite TIOCCONS."); % % +static int printf_lockcount; % + % +static void % +printf_lock(void) % +{ % + int timeout; % + % + timeout = 1000; % + do { % + if (atomic_cmpset_acq_int(&printf_lockcount, 0, 1)) % + return; % + DELAY(1000); % + } while (--timeout != 0); % + atomic_add_acq_int(&printf_lockcount, 1); % +} % + % +static void % +printf_unlock(void) % +{ % + % + atomic_add_rel_int(&printf_lockcount, -1); % +} % + % /* % * Warn that a system table is full. % @@ -198,5 +221,9 @@ % pca.flags = flags; % va_start(ap, fmt); % + if (pri != -1) % + printf_lock(); /* To serialize msgbuf. XXX: long-held lock? */ % kvprintf(fmt, putchar, &pca, 10, ap); % + if (pri != -1) % + printf_unlock(); % va_end(ap); % if (sess != NULL) % @@ -243,5 +270,7 @@ % % va_start(ap, fmt); % + printf_lock(); /* Even for TOLOG, for serializing msgbuf. */ % kvprintf(fmt, putchar, &pca, 10, ap); % + printf_unlock(); % va_end(ap); % % @@ -312,5 +341,7 @@ % #endif % % + printf_lock(); % retval = kvprintf(fmt, putchar, &pca, 10, ap); % + printf_unlock(); % va_end(ap); % % @@ -350,5 +381,7 @@ % #endif % % + printf_lock(); % retval = kvprintf(fmt, putchar, &pca, 10, ap); % + printf_unlock(); % % #ifdef PRINTF_BUFR_SIZE When recursion occurs, the locking is blown away, and the output occurs unserialized and _very slowly_ (about 1 character for every timeout period). You can contemplate the bug that causes the recursion while this is occuring. One such bug is in debugger entry. printf is called from kdb_enter improperly _before_ entering debugging context. So if you sprinkle kdb_enter calls in low-level functions like spinlock_enter, as sometimes is needed to debug such functions, you get either: - recursive panics from broken printfs - very slow output from my version. Putting breakpoints in the functions works better, at least on x86, since it gives a cleaner debugger entry with no buggy printf in it. Locking hacks for debugger mode then allow the console i/o to sort of work. Bruce