Re: [patch] annoying newline in kernel printf

On Tue, 9 Sep 2003, Pawel Worach wrote:

> Is this blank line necessary?
>
> -- dmesg snippet --
> APIC_IO: Testing 8254 interrupt delivery
> APIC_IO: routing 8254 via IOAPIC #0 intpin 2
>
> Timecounters tick every 10.000 msec
> acpi_cpu: throttling enabled, 2 steps (100% to 50.0%), currently 100.0%
> GEOM: create disk ad4 dp=0xc2490870

No.

> sys/kern/kern_tc.c:
>      $FreeBSD: src/sys/kern/kern_tc.c,v 1.157 2003/09/03 08:14:16 phk Exp $
>
> --- sys/kern/kern_tc.c.org      Tue Sep  9 00:21:30 2003
> +++ sys/kern/kern_tc.c  Tue Sep  9 00:21:57 2003
> _at__at_ -297,12 +297,11 _at__at_
>                         printf(" -- Insufficient hz, needs at least
> %u\n", u);

Hmm. this clause already had its own newline.

>                 }
>         } else if (tc->tc_quality >= 0 || bootverbose) {
> -               printf("Timecounter \"%s\" frequency %ju Hz quality %d",
> +               printf("Timecounter \"%s\" frequency %ju Hz quality %d\n",
>                     tc->tc_name, (intmax_t)tc->tc_frequency,
>                     tc->tc_quality);
>         }
>
> -       printf("\n");
>         tc->tc_next = timecounters;
>         timecounters = tc;
>         (void)tc->tc_get_timecount(tc);

Looks good.

I've changed a few more things in this function:

% Index: kern_tc.c
% ===================================================================
% RCS file: /home/ncvs/src/sys/kern/kern_tc.c,v
% retrieving revision 1.157
% diff -u -2 -r1.157 kern_tc.c
% --- kern_tc.c	3 Sep 2003 08:14:16 -0000	1.157
% +++ kern_tc.c	9 Sep 2003 13:11:20 -0000
% _at__at_ -287,31 +382,47 _at__at_
%  tc_init(struct timecounter *tc)
%  {
% -	unsigned u;
% +	u_int u;

Style fix.  `unsigned[ int]' is normally spelled u_in the kernel, and
kern_tc.c had no exceptions until this one was added.

%
% +	/*
% +	 * XXX this rounds down, but should round up by more than 1 or even
% +	 * multiply by a large factor to allow for some interrupt latency.
% +	 */
%  	u = tc->tc_frequency / tc->tc_counter_mask;

Grouse about a bogus limit.  If u is precisely `hz' (with no fractional
part), then counter overflow modulo the mask is certain unless clock
interrupts occur slightly more often than every 1/hz seconds (if the
timecounter reads in tc_windup() occured precisely every 1/hz seconds,
then they would always overflow).

%  	if (u > hz && tc->tc_quality >= 0) {
% -		tc->tc_quality = -2000;
% +		tc->tc_quality = -1000000;

This goes with an algorithm change later.  The magic -1000000 is
dummy_timecounter's quality.  We could use a smaller value to distinguish
turned-off timecounters from the dummy one, but the quality has to be
no greater than the dummy quality and not just negative to prevent use
with the changed algorithm.

%  		if (bootverbose) {
%  			printf("Timecounter \"%s\" frequency %ju Hz",
% -			    tc->tc_name, (intmax_t)tc->tc_frequency);
% -			printf(" -- Insufficient hz, needs at least %u\n", u);
% +			    tc->tc_name, (uintmax_t)tc->tc_frequency);

Fix a printf format error.  tc->tc_frequency has type u_int64_t which is
an unsigned type.  Converting it to the signed type intmax_t is bogus and
gives implementation-defined behaviour if the on overflow.  %ju is an
unsigned format.  Printing a signed type with this format gives undefined
behaviour if the value is negative.

% +			/* XXX this message is far too long for 80 columns. */
% +			printf(
% +		" -- insufficient HZ; HZ needs to be at least %u\n", u);

Improve some wording.  "Insufficient" was capitalized, and "hz" wasn't
capitalized.  Only HZ exists at the config level.  The wording after
the comma splice was worse than the comma splice.  I couldn't think
of better wording to keep the message shorter than 80 columns.  Improving
the wording made it longer.

%  		}
%  	} else if (tc->tc_quality >= 0 || bootverbose) {
% -		printf("Timecounter \"%s\" frequency %ju Hz quality %d",
% -		    tc->tc_name, (intmax_t)tc->tc_frequency,
% -		    tc->tc_quality);
% +		printf("Timecounter \"%s\" frequency %ju Hz quality %d\n",
% +		    tc->tc_name, (uintmax_t)tc->tc_frequency, tc->tc_quality);
%  	}
% -
% -	printf("\n");

Parts of this are your fix.

Fix the printf format error here too.  It's in even more places.  tsc.c
at least.

Fix bogus line break in the first printf.

Remove bogus blank line before the removed printf of the newline.  It was
more bogus when the newline was printed -- then it split up associated
printfs.

%  	tc->tc_next = timecounters;
%  	timecounters = tc;
% -	(void)tc->tc_get_timecount(tc);
% -	(void)tc->tc_get_timecount(tc);
% -	/* Never automatically use a timecounter with negative quality */
% -	if (tc->tc_quality < 0)
% -		return;

Simplify and improve algoithm by removing previous 3 lines.  We should
switch to timecounters that have higher quality than the one in use
even if their quality is negative, since they can hardly be worse than
the current one then.  Anyway, we shouldn't complicate things by creating
non-dummy timecounters with negative qualities except possibly to annull
them.

% -	if (tc->tc_quality < timecounter->tc_quality)
% -		return;
% -	timecounter = tc;
% +	if (tc->tc_quality > timecounter->tc_quality) {

Fix off by one error.  The old code attempted to round-robin among
timecounters of equal quality.  There is no point in that, but it
worked around the piix timecounter having a bogus quality.  The piix
has quality 0, which is the same as the quality of the i8254 timecounter;
the piix "just happens" to be attached after the i8254 and round-robin
makes the last one win, so the piix beat the i8254 despite its quality
being the same.  The piix actually has a quality more like that of the
acpi timecounter; it may even be the same hardware.

% +		(void)tc->tc_get_timecount(tc);
% +		(void)tc->tc_get_timecount(tc);

Old code moved.

% +		/*
% +		 * Switch to the new timecounter, and start using it
% +		 * immediately if the old one was the dummy one.  We
% +		 * don't always start using it immediately for fear
% +		 * of disturbing any locking bugs in tc_windup() more
% +		 * than necessary.
% +		 *
% +		 * Another problem here and in
% +		 * sysctl_kern_timecounter_hardware() is that when we
% +		 * don't start using the timecounter immediately, then
% +		 * its warmup may be too early to help.
% +		 */
% +		if (timecounter == &dummy_timecounter) {
% +			timecounter = tc;
% +			tc_windup();
% +		} else
% +			timecounter = tc;
% +	}

Conservative fix for early use of microtime(), etc.  microtime() still
works at boot time in RELENG_4, but was broken in -current in rev.1.125
of kern_tc.c by removing the unconditional call to tc_windup() from
the end of tc_init().  Winding up the timecounter cannot always wait
for the next call to hardclock(), since at boot time hardclock() won't
be called for up to several seconds and the dummy timecounter is useless
for timestamping real-time events.  Setting `timecounter' to the new
timecounter doesn't even give an unwound new timecounter, since
microtime(), etc. only uses timehands.

%  }
%

%%%
Index: kern_tc.c
===================================================================
RCS file: /home/ncvs/src/sys/kern/kern_tc.c,v
retrieving revision 1.157
diff -u -2 -r1.157 kern_tc.c
--- kern_tc.c	3 Sep 2003 08:14:16 -0000	1.157
+++ kern_tc.c	9 Sep 2003 13:35:45 -0000
_at__at_ -287,31 +382,47 _at__at_
 tc_init(struct timecounter *tc)
 {
-	unsigned u;
+	u_int u;

+	/*
+	 * XXX this rounds down, but should round up by more than 1 or even
+	 * multiply by a large factor to allow for some interrupt latency.
+	 */
 	u = tc->tc_frequency / tc->tc_counter_mask;
 	if (u > hz && tc->tc_quality >= 0) {
-		tc->tc_quality = -2000;
+		tc->tc_quality = -1000000;
 		if (bootverbose) {
 			printf("Timecounter \"%s\" frequency %ju Hz",
-			    tc->tc_name, (intmax_t)tc->tc_frequency);
-			printf(" -- Insufficient hz, needs at least %u\n", u);
+			    tc->tc_name, (uintmax_t)tc->tc_frequency);
+			/* XXX this message is far too long for 80 columns. */
+			printf(
+		" -- insufficient HZ; HZ needs to be at least %u\n", u);
 		}
 	} else if (tc->tc_quality >= 0 || bootverbose) {
-		printf("Timecounter \"%s\" frequency %ju Hz quality %d",
-		    tc->tc_name, (intmax_t)tc->tc_frequency,
-		    tc->tc_quality);
+		printf("Timecounter \"%s\" frequency %ju Hz quality %d\n",
+		    tc->tc_name, (uintmax_t)tc->tc_frequency, tc->tc_quality);
 	}
-
-	printf("\n");
 	tc->tc_next = timecounters;
 	timecounters = tc;
-	(void)tc->tc_get_timecount(tc);
-	(void)tc->tc_get_timecount(tc);
-	/* Never automatically use a timecounter with negative quality */
-	if (tc->tc_quality < 0)
-		return;
-	if (tc->tc_quality < timecounter->tc_quality)
-		return;
-	timecounter = tc;
+	if (tc->tc_quality > timecounter->tc_quality) {
+		(void)tc->tc_get_timecount(tc);
+		(void)tc->tc_get_timecount(tc);
+		/*
+		 * Switch to the new timecounter, and start using it
+		 * immediately if the old one was the dummy one.  We
+		 * don't always start using it immediately for fear
+		 * of disturbing the locking bugs in tc_windup() more
+		 * than necessary.
+		 *
+		 * Another problem here and in
+		 * sysctl_kern_timecounter_hardware() is that when we
+		 * don't start using the timecounter immediately, then
+		 * its warmup may be too early to help.
+		 */
+		if (timecounter == &dummy_timecounter) {
+			timecounter = tc;
+			tc_windup();
+		} else
+			timecounter = tc;
+	}
 }

%%%