Re: [PATCH v3] printk: Have printk() never buffer its data

[Steven Rostedt]

On Thu, 2012-06-28 at 09:38 +0200, Kay Sievers wrote:

> +static void cont_flush(void)
> +{
> +	if (cont.flushed)
> +		return;
> +	if (cont.len == 0)
> +		return;
> +
> +	log_store(cont.facility, cont.level, LOG_NOCONS, cont.ts_nsec,
> +		  NULL, 0, cont.buf, cont.len);
> +
> +	cont.flushed = true;
> +}
> +
> +static bool cont_add(int facility, int level, const char *text, size_t len)
> +{
> +	if (cont.len && cont.flushed)
> +		return false;
> +
> +	if (cont.len + len > sizeof(cont.buf)) {
> +		cont_flush();
> +		return false;
> +	}
> +
> +	if (!cont.len) {
> +		cont.facility = facility;
> +		cont.level = level;
> +		cont.owner = current;
> +		cont.ts_nsec = local_clock();
> +		cont.cons = 0;
> +		cont.flushed = false;
> +	}
> +
> +	memcpy(cont.buf + cont.len, text, len);
> +	cont.len += len;
> +	return true;
> +}
> +
> +static size_t cont_print_text(char *text, size_t size)
> +{
> +	size_t textlen = 0;
> +	size_t len;
> +
> +	if (cont.cons == 0) {
> +		textlen += print_time(cont.ts_nsec, text);
> +		size -= textlen;
> +	}
> +
> +	len = cont.len - cont.cons;
> +	if (len > 0) {
> +		if (len+1 > size)
> +			len = size-1;
> +		memcpy(text + textlen, cont.buf + cont.cons, len);
> +		textlen += len;
> +		cont.cons = cont.len;
> +	}
> +
> +	if (cont.flushed) {
> +		text[textlen++] = '\n';
> +		/* got everything, release buffer */
> +		cont.len = 0;
> +	}
> +	return textlen;
> +}
> +
>  asmlinkage int vprintk_emit(int facility, int level,
>  			    const char *dict, size_t dictlen,
>  			    const char *fmt, va_list args)
>  {
>  	static int recursion_bug;
> -	static char cont_buf[LOG_LINE_MAX];
> -	static size_t cont_len;
> -	static int cont_level;
> -	static struct task_struct *cont_task;
>  	static char textbuf[LOG_LINE_MAX];
>  	char *text = textbuf;
>  	size_t text_len;
> @@ -1348,7 +1442,8 @@ asmlinkage int vprintk_emit(int facility, int level,
>  		recursion_bug = 0;
>  		printed_len += strlen(recursion_msg);
>  		/* emit KERN_CRIT message */
> -		log_store(0, 2, NULL, 0, recursion_msg, printed_len);
> +		log_store(0, 2, LOG_DEFAULT, 0,
> +			  NULL, 0, recursion_msg, printed_len);
>  	}
>  
>  	/*
> @@ -1386,55 +1481,38 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	}
>  
>  	if (!newline) {
> -		if (cont_len && (prefix || cont_task != current)) {
> -			/*
> -			 * Flush earlier buffer, which is either from a
> -			 * different thread, or when we got a new prefix.
> -			 */
> -			log_store(facility, cont_level, NULL, 0, cont_buf, cont_len);
> -			cont_len = 0;
> -		}
> -
> -		if (!cont_len) {
> -			cont_level = level;
> -			cont_task = current;
> -		}
> +		/*
> +		 * Flush the conflicting buffer. An earlier newline was missing,
> +		 * or another task also prints continuation lines.
> +		 */
> +		if (cont.len && (prefix || cont.owner != current))
> +			cont_flush();
>  
> -		/* buffer or append to earlier buffer from the same thread */
> -		if (cont_len + text_len > sizeof(cont_buf))
> -			text_len = sizeof(cont_buf) - cont_len;
> -		memcpy(cont_buf + cont_len, text, text_len);
> -		cont_len += text_len;
> +		/* buffer line if possible, otherwise store it right away */
> +		if (!cont_add(facility, level, text, text_len))
> +			log_store(facility, level, LOG_DEFAULT, 0,
> +				  dict, dictlen, text, text_len);
>  	} else {
> -		if (cont_len && cont_task == current) {
> -			if (prefix) {
> -				/*
> -				 * New prefix from the same thread; flush. We
> -				 * either got no earlier newline, or we race
> -				 * with an interrupt.
> -				 */
> -				log_store(facility, cont_level,
> -					  NULL, 0, cont_buf, cont_len);
> -				cont_len = 0;
> -			}
> +		bool stored = false;
>  
> -			/* append to the earlier buffer and flush */
> -			if (cont_len + text_len > sizeof(cont_buf))
> -				text_len = sizeof(cont_buf) - cont_len;
> -			memcpy(cont_buf + cont_len, text, text_len);
> -			cont_len += text_len;
> -			log_store(facility, cont_level,
> -				  NULL, 0, cont_buf, cont_len);
> -			cont_len = 0;
> -			cont_task = NULL;
> -			printed_len = cont_len;
> -		} else {
> -			/* ordinary single and terminated line */
> -			log_store(facility, level,
> -				  dict, dictlen, text, text_len);
> -			printed_len = text_len;
> +		/*
> +		 * Flush the conflicting buffer. An earlier newline was missing,
> +		 * or we race with a continuation line from an interrupt.
> +		 */
> +		if (cont.len && prefix && cont.owner == current)
> +			cont_flush();
> +
> +		/* Merge with our buffer if possible; flush it in any case */
> +		if (cont.len && cont.owner == current) {
> +			stored = cont_add(facility, level, text, text_len);
> +			cont_flush();
>  		}


I wonder if it would be better to do the following for the above two
ifs:

	if (cont.len && cont.owner == current) {
		if (!prefix)
			stored = cont_add(facility, level, text, text_len);
		cont_flush();
	}

If the prefix was true, then the cont.flush would be set when cont_add()
is called, and the first thing that cont_add() does:

	if (cont.len && cont.flushed)
		return false;

which would always be true (returning false) if prefix was set.

And the second cont_flush() is a nop due to it doing:

	if (cont.flushed)
		return;

-- Steve


> +
> +		if (!stored)
> +			log_store(facility, level, LOG_DEFAULT, 0,
> +				  dict, dictlen, text, text_len);
>  	}
> +	printed_len += text_len;
>  
>  	/*
>  	 * Try to acquire and then immediately release the console semaphore.
> @@ -1521,11 +1599,18 @@ EXPORT_SYMBOL(printk);
>  #else
>  
>  #define LOG_LINE_MAX 0
> +static struct cont {
> +	size_t len;
> +	size_t cons;
> +	u8 level;
> +	bool flushed:1;
> +} cont;
>  static struct log *log_from_idx(u32 idx) { return NULL; }
>  static u32 log_next(u32 idx) { return 0; }
>  static void call_console_drivers(int level, const char *text, size_t len) {}
>  static size_t msg_print_text(const struct log *msg, bool syslog,
>  			     char *buf, size_t size) { return 0; }
> +static size_t cont_print_text(char *text, size_t size) { return 0; }
>  
>  #endif /* CONFIG_PRINTK */
>  
> @@ -1817,6 +1902,7 @@ static u32 console_idx;
>   */
>  void console_unlock(void)
>  {
> +	static char text[LOG_LINE_MAX];
>  	static u64 seen_seq;
>  	unsigned long flags;
>  	bool wake_klogd = false;
> @@ -1829,10 +1915,23 @@ void console_unlock(void)
>  
>  	console_may_schedule = 0;
>  
> +	/* flush buffered message fragment immediately to console */
> +	raw_spin_lock_irqsave(&logbuf_lock, flags);
> +	if (cont.len && (cont.cons < cont.len || cont.flushed)) {
> +		size_t len;
> +
> +		len = cont_print_text(text, sizeof(text));
> +		raw_spin_unlock(&logbuf_lock);
> +		stop_critical_timings();
> +		call_console_drivers(cont.level, text, len);
> +		start_critical_timings();
> +		local_irq_restore(flags);
> +	} else
> +		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
> +
>  again:
>  	for (;;) {
>  		struct log *msg;
> -		static char text[LOG_LINE_MAX];
>  		size_t len;
>  		int level;
>  
> @@ -1847,13 +1946,22 @@ again:
>  			console_seq = log_first_seq;
>  			console_idx = log_first_idx;
>  		}
> -
> +skip:
>  		if (console_seq == log_next_seq)
>  			break;
>  
>  		msg = log_from_idx(console_idx);
> -		level = msg->level & 7;
> +		if (msg->flags & LOG_NOCONS) {
> +			/*
> +			 * Skip record we have buffered and already printed
> +			 * directly to the console when we received it.
> +			 */
> +			console_idx = log_next(console_idx);
> +			console_seq++;
> +			goto skip;
> +		}
>  
> +		level = msg->level;
>  		len = msg_print_text(msg, false, text, sizeof(text));
>  
>  		console_idx = log_next(console_idx);
> 


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/