Re: [PATCH v3] Make fprintf() function to multithread-safe

[Peng Haitao <penght at cn dot fujitsu dot com>]

On 07/24/2012 08:57 AM, Carlos O'Donell wrote:
> I agree with Roland here.
> 
> We need to see some real investigation and performance analysis.
> 
> Making fprintf multithread-safe is important, but we should not do
> so using a heavy hammer approach involving global locks.
> 
> Do you have any workloads that you can use for performance testing?
> 

I execute fprintf() with 10000000 times. the time is as follows:
Before the patch, execute the test program with 3 times:

# gcc -o fprintf fprintf_test.c
# perf stat -e instructions -- ./fprintf > /dev/null

 Performance counter stats for './fprintf':

    30,029,483,759 instructions              #    0.00  insns per cycle        

       7.529193862 seconds time elapsed

# perf stat -e instructions -- ./fprintf > /dev/null

 Performance counter stats for './fprintf':

    30,030,491,388 instructions              #    0.00  insns per cycle        

       7.509089783 seconds time elapsed

# perf stat -e instructions -- ./fprintf > /dev/null

 Performance counter stats for './fprintf':

    30,029,273,153 instructions              #    0.00  insns per cycle        

       7.533755240 seconds time elapsed


After the patch, execute the test program with 3 times:

# gcc -o fprintf_new fprintf_test.c -Wl,-dynamic-linker=/home/pht/sdb2/work/glibc-install/lib/ld-linux-x86-64.so.2
# perf stat -e instructions -- ./fprintf_new > /dev/null

 Performance counter stats for './fprintf_new':

    39,694,589,611 instructions              #    0.00  insns per cycle        

       9.620096738 seconds time elapsed

# perf stat -e instructions -- ./fprintf_new > /dev/null

 Performance counter stats for './fprintf_new':

    39,693,829,629 instructions              #    0.00  insns per cycle        

       9.413244651 seconds time elapsed

# perf stat -e instructions -- ./fprintf_new > /dev/null

 Performance counter stats for './fprintf_new':

    39,694,838,263 instructions              #    0.00  insns per cycle        

       9.690116102 seconds time elapsed


Test environment:
Kernel: 2.6.32-279.el6.x86_64
CPU:    Intel(R) Xeon(R) CPU           E5506  @ 2.13GHz
Memory: 12G
OS:     Red Hat Enterprise Linux Server release 6.3 (Santiago)


The test method is OK?
Thanks.

-- 
Best Regards,
Peng

#define _GNU_SOURCE
#include <stdio.h>
#include <stdlib.h>
#include <printf.h>

#define MAX_COUNT 10000000

typedef struct
{
	char *name;
} Widget;

int print_widget (FILE *stream, const struct printf_info *info,
		  const void *const *args)
{
	const Widget *w;
	char *buffer;
	int len;

	/* Format the output into a string. */
	w = *((const Widget **) (args[0]));
	len = asprintf (&buffer, "<Widget %p: %s>", w, w->name);
	if (len == -1)
		return -1;

	/* Pad to the minimum field width and print to the stream. */
	len = fprintf (stream, "%*s",
		      (info->left ? -info->width : info->width), buffer);

	/* Clean up and return. */
	free (buffer);
	return len;
}

int print_widget_arginfo (const struct printf_info *info, size_t n,
			  int *argtypes)
{
	/* We always take exactly one argument and this is a pointer to the
	*  structure. */
	if (n > 0)
		argtypes[0] = PA_POINTER;
	return 1;
}
 
int main (void)
{
	int i = 0;
	/* Make a widget to print. */
	Widget mywidget;
	mywidget.name = "mywidget";

	/* Register the print function for widgets. */
	register_printf_specifier ('W', print_widget,
				  (printf_arginfo_size_function*) print_widget_arginfo);

	while (i++ < MAX_COUNT)
		fprintf (stdout, "|%W|\n", &mywidget);

	return 0;
}