Date: Fri, 17 Sep 2010 15:00:21 -0700 From: mdf@FreeBSD.org To: FreeBSD Arch <freebsd-arch@freebsd.org> Cc: Poul-Henning Kamp <phk@phk.freebsd.dk> Subject: Towards a One True Printf Message-ID: <AANLkTi=uZqxw-VQ=K3AayWxewmZP8qCq1%2B-sdRs4m=Rc@mail.gmail.com>
next in thread | raw e-mail | index | archive | help
In an attempt to move towards a one true printf, I copied the base printf(3) implementation and changed the parameters to be similar to that of kvprintf(9), with a generic callback function on each print group. The callback can easily be essentially the io_put() methods used for printf(3) but have the possibility of being something else too. I used two different callback signatures -- the first is an optimized version that takes a char array (or presumably a wide char array to implement wprintf(3)), and the second is identical to the callback for kvprintf(9). http://people.freebsd.org/~mdf/vcb_printf.c http://people.freebsd.org/~mdf/vcb_printf2.c With changes in hand, I wrote a small user-space utility to benchmark the existing fprintf and sprintf versus the new one. Note that the my_fprintf() function essentially borrows from the guts of printfcommon.h. This http://people.freebsd.org/~mdf/printf_test.c The numbers I get I found rather interesting (also, I appear to be incompetent at calculating standard deviations; I'm sure someone will correct my code). # ./printf_test sprintf : avg 0.090116202 sec, stdd 1.429e+10 my_sprintf : avg 0.069918215 sec, stdd 1.167e+10 my_sprintf2: avg 0.174028095 sec, stdd 1.167e+10 fprintf /dev/null: avg 0.077871461 sec, stdd 1.65e+10 my_fprintf /dev/null: avg 0.102162816 sec, stdd 8.25e+09 my_fprintf2 /dev/null: avg 0.307952770 sec, stdd 1.65e+10 fprintf /tmp: avg 0.169936961 sec, stdd 1.167e+10 my_fprintf /tmp: avg 0.199943344 sec, stdd 1.167e+10 my_fprintf2 /tmp: avg 0.399886075 sec, stdd 1.167e+10 my_fwrite /tmp: avg 0.210000656 sec, stdd 1.167e+10 I am unsurprised that the character-by-character callback is slower than bulk; in fact I didn't roll up the bulk callback until I saw how miserable the character-by-character callback was. I put the code and numbers up for both because this also indicates the likelihood of a speedup in the kernel by doing a bulk callback for sprintf and sbuf operations. The new implementation is significantly faster when doing sprintf(3), significantly slower when printing to /dev/null, and slightly slower when printing to a file using an iovec, and slightly more slow using a naieve fwrite(3) callback. In my case, /tmp is a UFS2 filesystem. My thought would be that, if we have a core implementation like cb_printf that can be used in both the kernel and libc/stdio, it would be fewer sources to maintain. Also, the kernel cannot use the existing FILE based printf(3) but both sources can use a callback-based printf. I would like to discuss at some point after this adding a generic printf format specifier that basically takes a function pointer and argument and uses that to print. Implementing that for both kernel and userspace would be easier with a single root printf implementation. So, thoughts? Is the performance loss here acceptable, and is there something I missed in terms of making it run faster when printing to files? Thanks, matthew
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?AANLkTi=uZqxw-VQ=K3AayWxewmZP8qCq1%2B-sdRs4m=Rc>