From owner-freebsd-arch@FreeBSD.ORG Fri Sep 17 22:09:02 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 C14F11065672 for ; Fri, 17 Sep 2010 22:09:02 +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 854408FC08 for ; Fri, 17 Sep 2010 22:09:02 +0000 (UTC) Received: by iwn34 with SMTP id 34so2753896iwn.13 for ; Fri, 17 Sep 2010 15:09:02 -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 :in-reply-to:references:date:x-google-sender-auth:message-id:subject :from:to:cc:content-type:content-transfer-encoding; bh=BG6j0fzGOTd990fSrVrXCF1skOc3Z5bXus9IVzFiZ9c=; b=rJWbqnQ5radleUB6cwSGabWEaFmyS8WkJhZZlnjNpS3hbZG1ufxAemKUbl47MQwv6y bzkNJHF+bmiQd2bBNziqkqtxWTF8u+TP94Cmspzw4e+OSiqcoDQQ98T4jobPfpF0v93d ZjmCO+Gx+AjWHjp5i3I9ThmVxuAB0t+eNz/c8= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=mime-version:sender:in-reply-to:references:date :x-google-sender-auth:message-id:subject:from:to:cc:content-type :content-transfer-encoding; b=JUCmb6llMnXhzSJxEw98wRXZMKCOqWEKGcxfYm4Jk+Qxiofkr3WXwQKdENTGZF2WyF n+rEKeGpAKbiBB5nC4GUchZ7FPhVw8X3lq4EJRhgIp52/A8uIBDysZQKSRraBf9dioJW XuLZgcJGc+iBcF38prbf36D/U3YvAGQhnOraU= MIME-Version: 1.0 Received: by 10.231.31.129 with SMTP id y1mr5881282ibc.45.1284761341838; Fri, 17 Sep 2010 15:09:01 -0700 (PDT) Sender: mdf356@gmail.com Received: by 10.231.187.71 with HTTP; Fri, 17 Sep 2010 15:09:01 -0700 (PDT) In-Reply-To: References: Date: Fri, 17 Sep 2010 15:09:01 -0700 X-Google-Sender-Auth: pR0vIg6Rr2RVsWhboFV8qTu76vs Message-ID: From: mdf@FreeBSD.org To: FreeBSD Arch Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Cc: Poul-Henning Kamp Subject: Re: 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:09:02 -0000 On Fri, Sep 17, 2010 at 3:00 PM, wrote: > 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. =A0The callback can easily be essentially the io_put() methods > used for printf(3) but have the possibility of being something else > too. =A0I 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. =A0Note that the > my_fprintf() function essentially borrows from the guts of > printfcommon.h. =A0This > > 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 =A0 =A0: 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 =A0 =A0 /dev/null: avg 0.077871461 sec, stdd 1.65e+10 > my_fprintf =A0/dev/null: avg 0.102162816 sec, stdd 8.25e+09 > my_fprintf2 /dev/null: avg 0.307952770 sec, stdd 1.65e+10 > > fprintf =A0 =A0 /tmp: avg 0.169936961 sec, stdd 1.167e+10 > my_fprintf =A0/tmp: avg 0.199943344 sec, stdd 1.167e+10 > my_fprintf2 /tmp: avg 0.399886075 sec, stdd 1.167e+10 > my_fwrite =A0 /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. =A0I 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. =A0In 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. =A0Also, 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. =A0Implementing that for both kernel > and userspace would be easier with a single root printf > implementation. > > So, thoughts? =A0Is the performance loss here acceptable, and is there > something I missed in terms of making it run faster when printing to > files? Also, here is a diff from vfprintf.c to vcb_printf.c to show what really changed: http://people.freebsd.org/~mdf/vfprintf-to-vcb_printf.diff Last, to make all this compile I had to add [v]cb_printf to libc's Symbol.map and also I added __sfvwrite so my user-land performance utility would build. Thanks, matthew