From owner-freebsd-arch@FreeBSD.ORG Fri Sep 17 22:00:22 2010 Return-Path: Delivered-To: freebsd-arch@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id CFD601065670 for ; Fri, 17 Sep 2010 22:00:22 +0000 (UTC) (envelope-from mdf356@gmail.com) Received: from mail-iw0-f182.google.com (mail-iw0-f182.google.com [209.85.214.182]) by mx1.freebsd.org (Postfix) with ESMTP id 97F638FC08 for ; Fri, 17 Sep 2010 22:00:22 +0000 (UTC) Received: by iwn34 with SMTP id 34so2745913iwn.13 for ; Fri, 17 Sep 2010 15:00:21 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:mime-version:received:sender:received:date :x-google-sender-auth:message-id:subject:from:to:cc:content-type; bh=woSfgqRAfkyGzlQMA7yezI9OVBCKmzcIETEPtJK0GNM=; b=AKWjiIPqKr3puMy5P5JiL+/QKsFbr69Udw9evn1Pe1iyYfzPri2JU1qiRwfOVIVX1c 4MZi0xquSLrcm0DzwRKeshWn7geXizXsLEBvfDu0R58IS8fan+PEOD9e1v34C4z1tmuL ZAOh6CISrbZkTO3ay1l9l+wbQyioZZy1w2tF0= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=mime-version:sender:date:x-google-sender-auth:message-id:subject :from:to:cc:content-type; b=rmD4elx5Y5H6Gf15hVnRwNGIIcks1SgnzCkACozTE8ZT5c+n4iXACT3PSmWojrmMrt 88ksPYHke/kFK0B1uHS/Wg1ZF41aPEwrN0cGS/3iXR3jwrtywSbmsf2VQSdD4WT0mpkr mE81Ycvds/X91EVdtYwkJTriD1Vo9Wcfp6dvg= MIME-Version: 1.0 Received: by 10.231.11.9 with SMTP id r9mr5855454ibr.47.1284760821712; Fri, 17 Sep 2010 15:00:21 -0700 (PDT) Sender: mdf356@gmail.com Received: by 10.231.187.71 with HTTP; Fri, 17 Sep 2010 15:00:21 -0700 (PDT) Date: Fri, 17 Sep 2010 15:00:21 -0700 X-Google-Sender-Auth: NPvV5G8STDOCYP4sd8Hu_Q-jPxQ Message-ID: From: mdf@FreeBSD.org To: FreeBSD Arch Content-Type: text/plain; charset=ISO-8859-1 Cc: Poul-Henning Kamp Subject: Towards a One True Printf X-BeenThere: freebsd-arch@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussion related to FreeBSD architecture List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 17 Sep 2010 22:00:23 -0000 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