From mboxrd@z Thu Jan  1 00:00:00 1970
Message-ID: <40C8A583.7000504@gmail.com>
Date: Thu, 10 Jun 2004 11:16:35 -0700
From: Matt Pidd-Cheshire <mattjpc@gmail.com>
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US;
	rv:1.6) Gecko/20040113
MIME-Version: 1.0
To: Fans of the OS Plan 9 from Bell Labs <9fans@cse.psu.edu>
Subject: [9fans] freebsd v. plan9 - profile results (long)
Content-Type: text/plain; charset=us-ascii; format=flowed
Content-Transfer-Encoding: 7bit
Topicbox-Message-UUID: 9b5ef24c-eacd-11e9-9e20-41e7f4b1d025


I really hope someone can help here ... [please nice moderator
person post this; my last two posts never appeared] ...

WRT my last lot of complaining posts about speed problems under
plan9 ...

After discovering that I had somehow zapped the original code I had to do
some fast rewriting. Lots of coffee and some tests later, produced the
following information. Same conditions as before; same machine, *almost*
identical code (see diffs below) - functionally no different as the
profiles should confirm, obviously identical garbage in and out.

The kfs on the plan9 machine is -rb1024 but I gave it lots of buffer
and did a "cat mtent13.txt>/dev/null" to suck it into the cache before
running. same with freebsd. watched closely no visible disc accessing
during each run.

gcc with *no* special options apart from -p, ditto for 8c.

if anyone wants the source i can mail it in a bzip2'ed tarfile (6.5k)
  - and you can show me how slow my machine is.  ;-)

looking at the profile summaries tells me I know too little about plan9
or freebsd. all i know is that the bottom line is vastly different :

    plan9   - 93.152 seconds
    bsd     -  3.750  seconds

rob pike suggested that the cpu cache might be disabled under plan9,
if so please to tell me how i can enable it; i'll gladly hack the
kernel source (mine) if i can get a little guidance, and a bit of
sleep.

thanks

:-)

|mattjpc

----
"If he'd just pay me what he's spending to stop me robbing
him, I'd stop robbing him!" -- (Paul Newman as) Butch Cassidy


--------------------- dmesg output ------------------------

Copyright (c) 1992-2004 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
         The Regents of the University of California. All rights reserved.
FreeBSD 5.2-RELEASE #0: Sun Jan 11 04:21:45 GMT 2004
     root@wv1u.btc.adaptec.com:/usr/obj/usr/src/sys/GENERIC
Preloaded elf kernel "/boot/kernel/kernel" at 0xc09e1000.
MPTable: <COMPAQ               >
Timecounter "i8254" frequency 1193182 Hz quality 0
CPU: Intel(R) Celeron(TM) CPU                1300MHz (1295.62-MHz 686-class
CPU)
   Origin = "GenuineIntel"  Id = 0x6b1  Stepping = 1
 
Features=0x383fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,MMX,FXSR,SSE>
real memory  = 536870912 (512 MB)
avail memory = 511840256 (488 MB)
ioapic0: Changing APIC ID to 8
ioapic0: Assuming intbase of 0
ioapic0 <Version 2.0> irqs 0-23 on motherboard
Pentium Pro MTRR support enabled
npx0: [FAST]
npx0: <math processor> on motherboard
npx0: INT 16 interface
pcibios: BIOS version 2.10
Using $PIR table, 7 entries at 0xc00e8be0
pcib0: <MPTable Host-PCI bridge> at pcibus 0 on motherboard
pci0: <PCI bus> on pcib0
pcib0: slot 31 INTD routed to irq 19
pcib0: slot 31 INTC routed to irq 23
pcib1: <MPTable PCI-PCI bridge> at device 30.0 on pci0
pci2: <PCI bus> on pcib1
pcib1: slot 11 INTA routed to irq 17
pcib1: slot 13 INTA routed to irq 18
pcib1: slot 15 INTA routed to irq 19
pci2: <multimedia, audio> at device 11.0 (no driver attached)
pci2: <input device> at device 11.1 (no driver attached)
dc0: <ADMtek AN985 10/100BaseTX> port 0x1000-0x10ff mem
0x41000000-0x410003ff irq 18 at device 13.0 on pci2
dc0: Ethernet address: 00:03:6d:20:1b:3e
miibus0: <MII bus> on dc0
ukphy0: <Generic IEEE 802.3u media interface> on miibus0
ukphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
pci2: <display, VGA> at device 15.0 (no driver attached)
isab0: <PCI-ISA bridge> at device 31.0 on pci0
isa0: <ISA bus> on isab0
atapci0: <Intel ICH2 UDMA100 controller> port 0x2480-0x248f at device 31.1
on pci0
ata0: at 0x1f0 irq 14 on atapci0
ata0: [MPSAFE]
ata1: at 0x170 irq 15 on atapci0
ata1: [MPSAFE]
uhci0: <Intel 82801BA/BAM (ICH2) USB controller USB-A> port 0x2440-0x245f
irq 19 at device 31.2 on pci0
usb0: <Intel 82801BA/BAM (ICH2) USB controller USB-A> on uhci0
usb0: USB revision 1.0
uhub0: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhci1: <Intel 82801BA/BAM (ICH2) USB controller USB-B> port 0x2460-0x247f
irq 23 at device 31.4 on pci0
usb1: <Intel 82801BA/BAM (ICH2) USB controller USB-B> on uhci1
usb1: USB revision 1.0
uhub1: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
orm0: <Option ROMs> at iomem 0xe0000-0xeffff,0xc0000-0xc7fff on isa0
pmtimer0 on isa0
atkbdc0: <Keyboard controller (i8042)> at port 0x64,0x60 on isa0
atkbd0: <AT Keyboard> flags 0x1 irq 1 on atkbdc0
kbd0 at atkbd0
psm0: <PS/2 Mouse> irq 12 on atkbdc0
psm0: model MouseMan+, device ID 0
fdc0: ready for input in output
fdc0: cmd 3 failed at out byte 1 of 3
ppc0: <Parallel port> at port 0x378-0x37f irq 7 on isa0
ppc0: SMC-like chipset (ECP/EPP/PS2/NIBBLE) in COMPATIBLE mode
ppc0: FIFO with 16/16/13 bytes threshold
ppbus0: <Parallel port bus> on ppc0
plip0: <PLIP network interface> on ppbus0
lpt0: <Printer> on ppbus0
lpt0: Interrupt-driven port
ppi0: <Parallel I/O> on ppbus0
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x300>
sio0 at port 0x3f8-0x3ff irq 4 flags 0x10 on isa0
sio0: type 16550A
sio1 at port 0x2f8-0x2ff irq 3 on isa0
sio1: type 16550A
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
unknown: <PNP0401> can't assign resources (port)
unknown: <PNP0501> can't assign resources (port)
unknown: <PNP0501> can't assign resources (port)
fdc1: cannot reserve I/O port range (1 ports)
unknown: <PNP0303> can't assign resources (port)
unknown: <PNP0f13> can't assign resources (irq)
Timecounter "TSC" frequency 1295624104 Hz quality 800
Timecounters tick every 10.000 msec
GEOM: create disk ad0 dp=0xc47f9d60
ad0: 38166MB <WDC WD400BB-00AUA1> [77545/16/63] at ata0-master UDMA100
GEOM: create disk ad1 dp=0xc47f9960
ad1: 38166MB <WDC WD400EB-11CPF0> [77545/16/63] at ata0-slave UDMA100
acd0: DVDROM <DVD-ROM BDV212B> at ata1-master PIO4
GEOM: create disk ad3 dp=0xc483ac60
ad3: 114473MB <WDC WD1200BB-00CAA0> [232581/16/63] at ata1-slave UDMA100
Mounting root from ufs:/dev/ad1s1a
pcm0: <Creative EMU10K1> port 0x1400-0x141f irq 17 at device 11.0 on pci2
pcm0: <SigmaTel STAC9721/23 AC97 Codec>


----------- plan9 run and complete prof output -------------

   %   Time      Calls   Name
12.1  11.249 40719877   cmp_entry
  8.8   8.202  3495522   avl_probe
  7.8   7.309 40719877   strcmp
  4.6   4.251 27523255   ltreewalk
  4.5   4.228  6881958   pooladd
  4.5   4.226  6880431   pooldel
  4.2   3.892  3544435   poolallocl
  3.7   3.462  3495523   getword
  3.6   3.311  3545962   kemb
  3.0   2.836  3446611   poolfreel
  2.9   2.744  3544435   malloc
  2.6   2.416        1   main
  2.4   2.249  3544435   poolalloc
  2.4   2.200  3446611   poolfree
  2.2   2.052  6991046   plock
  2.2   2.006  6880431   treedelete
  2.1   1.971 14723032   tolower
  2.1   1.953 14086024   dsize2bsize
  2.1   1.949  6991046   punlock
  2.1   1.942  6880435   treeinsert
  2.1   1.912  6991048   lock
  2.0   1.891  3458852   blockcheck
  1.6   1.527  3495522   new_word
  1.2   1.091  3545962   blocksetdsize
  1.1   1.061  6991048   _tas
  1.1   1.055  3335994   blockmerge
  1.1   0.991  3446611   free
  1.0   0.955  3495522   strncpy
  1.0   0.954  6872219   blocksetsize
  1.0   0.933  6880431   listdelete
  1.0   0.924  6881958   listadd
  1.0   0.921  6991048   unlock
  0.7   0.654  3545965   treelookupgt
  0.5   0.484  3544435   B2D
  0.5   0.472  3544435   setrealloctag
  0.5   0.470  3451192   getdsize
  0.5   0.470  3446611   D2B
  0.5   0.469  3495523   feof
  0.5   0.467  3544435   setmalloctag
  0.5   0.464  3544435   getcallerpc
  0.1   0.089    97822   _fmtdispatch
  0.0   0.042    97822   _fmtcpy
  0.0   0.039    48911   write
  0.0   0.035    48911   vfprint
  0.0   0.035    48911   fmtstrcpy
  0.0   0.034    48911   _ifmt
  0.0   0.029    48911   dofmt
  0.0   0.025        1   avl_walk
  0.0   0.023    48911   print_node
  0.0   0.019   146733   chartorune
  0.0   0.018    48911   _fmtFdFlush
  0.0   0.017    97822   _fmtpad
  0.0   0.016    48911   print
  0.0   0.015    48911   new_node
  0.0   0.015    97822   fmtfmt
  0.0   0.015    48912   xmalloc
  0.0   0.015    48911   _strfmt
  0.0   0.011     4803   read
  0.0   0.009    48911   strlen
  0.0   0.009    48911   utflen
  0.0   0.008     1530   poolnewarena
  0.0   0.006    48911   fmtfdinit
  0.0   0.005     1529   arenamerge
  0.0   0.004     4802   _IO_getc
  0.0   0.002     1529   blockgrow
  0.0   0.002     3059   arenasetsize
  0.0   0.001     1530   sbrkalloc
  0.0   0.001     1530   sbrk
  0.0   0.000     1529   sbrkmerge
  0.0   0.000        1   atol
  0.0   0.000        1   memset
  0.0   0.000        1   avl_create
  0.0   0.000        1   getpid
  0.0   0.000        1   setvbuf
  0.0   0.000        1   _IO_setvbuf
  0.0   0.000        2   _fmtinstall
  0.0   0.000     1530   bsize2asize
  0.0   0.000        2   _fmtunlock
  0.0   0.000        2   _fmtlock


---------- freebsd run and complete gprof output ---------------

call graph profile:
           The sum of self and descendents is the major sort
           for this listing.

           function entries:

index     the index of the function in the call graph
           listing, as an aid to locating it (see below).

%time     the percentage of the total time of the program
           accounted for by this function and its
           descendents.

self      the number of seconds spent in this function
           itself.

descendents
           the number of seconds spent in the descendents of
           this function on behalf of this function.

called    the number of times this function is called (other
           than recursive calls).

self      the number of times this function calls itself
           recursively.

name      the name of the function, with an indication of
           its membership in a cycle, if any.

index     the index of the function in the call graph
           listing, as an aid to locating it.



           parent listings:

self*     the number of seconds of this function's self time
           which is due to calls from this parent.

descendents*
           the number of seconds of this function's
           descendent time which is due to calls from this
           parent.

called**  the number of times this function is called by
           this parent.  This is the numerator of the
           fraction which divides up the function's time to
           its parents.

total*    the number of times this function was called by
           all of its parents.  This is the denominator of
           the propagation fraction.

parents   the name of this parent, with an indication of the
           parent's membership in a cycle, if any.

index     the index of this parent in the call graph
           listing, as an aid in locating it.



           children listings:

self*     the number of seconds of this child's self time
           which is due to being called by this function.

descendent*
           the number of seconds of this child's descendent's
           time which is due to being called by this
           function.

called**  the number of times this child is called by this
           function.  This is the numerator of the
           propagation fraction for this child.

total*    the number of times this child is called by all
           functions.  This is the denominator of the
           propagation fraction.

children  the name of this child, and an indication of its
           membership in a cycle, if any.

index     the index of this child in the call graph listing,
           as an aid to locating it.



           * these fields are omitted for parents (or
           children) in the same cycle as the function.  If
           the function (or child) is a member of a cycle,
           the propagated times and propagation denominator
           represent the self time and descendent time of the
           cycle as a whole.

           ** static-only parents and children are indicated
           by a call count of 0.



           cycle listings:
           the cycle as a whole is listed with the same
           fields as a function entry.  Below it are listed
           the members of the cycle, and their contributions
           to the time and call counts of the cycle.


granularity: each sample hit covers 4 byte(s) for 0.03% of 3.75 seconds

                                   called/total       parents
index  %time    self descendents  called+self    name           index
                                   called/total       children

                                                      <spontaneous>
[1]    100.0    0.24        3.51                 main [1]
                 1.99        0.41 3495522/3495522     avl_probe [2]
                 0.35        0.66 3495523/3495523     getword [3]
                 0.07        0.00 3495522/3495522     new_word [8]
                 0.02        0.01       1/1           avl_walk [9]
                 0.00        0.00       1/1           avl_create [13]

-----------------------------------------------

                 1.99        0.41 3495522/3495522     main [1]
[2]     63.9    1.99        0.41 3495522         avl_probe [2]
                 0.40        0.00 40719877/40719877     cmp_entry [5]
                 0.00        0.00   48911/48911       new_node [12]

-----------------------------------------------

                 0.35        0.66 3495523/3495523     main [1]
[3]     27.1    0.35        0.66 3495523         getword [3]
                 0.33        0.20 19664049/19664049     __istype [4]
                 0.14        0.00 14723032/14723032     __tolower [7]

-----------------------------------------------

                 0.33        0.20 19664049/19664049     getword [3]
[4]     14.1    0.33        0.20 19664049         __istype [4]
                 0.20        0.00 19664049/19664049     __maskrune [6]

-----------------------------------------------

                 0.40        0.00 40719877/40719877     avl_probe [2]
[5]     10.8    0.40        0.00 40719877         cmp_entry [5]

-----------------------------------------------

                 0.20        0.00 19664049/19664049     __istype [4]
[6]      5.3    0.20        0.00 19664049         __maskrune [6]

-----------------------------------------------

                 0.14        0.00 14723032/14723032     getword [3]
[7]      3.6    0.14        0.00 14723032         __tolower [7]

-----------------------------------------------

                 0.07        0.00 3495522/3495522     main [1]
[8]      1.8    0.07        0.00 3495522         new_word [8]

-----------------------------------------------

                 0.02        0.01       1/1           main [1]
[9]      0.9    0.02        0.01       1         avl_walk [9]
                 0.01        0.00   48911/48911       print_node [10]

-----------------------------------------------

                 0.01        0.00   48911/48911       avl_walk [9]
[10]     0.3    0.01        0.00   48911         print_node [10]

-----------------------------------------------

                 0.00        0.00       1/48912       avl_create [13]
                 0.00        0.00   48911/48912       new_node [12]
[11]     0.1    0.00        0.00   48912         xmalloc [11]

-----------------------------------------------

                 0.00        0.00   48911/48911       avl_probe [2]
[12]     0.1    0.00        0.00   48911         new_node [12]
                 0.00        0.00   48911/48912       xmalloc [11]

-----------------------------------------------

                 0.00        0.00       1/1           main [1]
[13]     0.0    0.00        0.00       1         avl_create [13]
                 0.00        0.00       1/48912       xmalloc [11]

-----------------------------------------------





flat profile:

  %         the percentage of the total running time of the
time       program used by this function.

cumulative a running sum of the number of seconds accounted
  seconds   for by this function and those listed above it.

  self      the number of seconds accounted for by this
seconds    function alone.  This is the major sort for this
            listing.

calls      the number of times this function was invoked, if
            this function is profiled, else blank.

  self      the average number of milliseconds spent in this
ms/call    function per call, if this function is profiled,
            else blank.

  total     the average number of milliseconds spent in this
ms/call    function and its descendents per call, if this
            function is profiled, else blank.

name       the name of the function.  This is the minor sort
            for this listing. The index shows the location of
            the function in the gprof listing. If the index is
            in parenthesis it shows where it would appear in
            the gprof listing if it were to be printed.


granularity: each sample hit covers 4 byte(s) for 0.03% of 3.75 seconds

   %   cumulative   self              self     total
  time   seconds   seconds    calls  ms/call  ms/call  name
  53.0       1.99     1.99  3495522     0.00     0.00  avl_probe [2]
  10.8       2.39     0.40 40719877     0.00     0.00  cmp_entry [5]
   9.4       2.74     0.35  3495523     0.00     0.00  getword [3]
   8.8       3.07     0.33 19664049     0.00     0.00  __istype [4]
   6.4       3.31     0.24                             main [1]
   5.3       3.51     0.20 19664049     0.00     0.00  __maskrune [6]
   3.6       3.65     0.14 14723032     0.00     0.00  __tolower [7]
   1.8       3.72     0.07  3495522     0.00     0.00  new_word [8]
   0.5       3.74     0.02        1    19.53    32.23  avl_walk [9]
   0.3       3.75     0.01    48911     0.00     0.00  print_node [10]
   0.1       3.75     0.00    48912     0.00     0.00  xmalloc [11]
   0.0       3.75     0.00    48911     0.00     0.00  new_node [12]
   0.0       3.75     0.00        1     0.00     0.00  avl_create [13]

Index by function name

    [4] __istype              [9] avl_walk              [8] new_word 

    [6] __maskrune            [5] cmp_entry            [10] print_node 

    [7] __tolower             [3] getword              [11] xmalloc 

   [13] avl_create            [1] main
    [2] avl_probe            [12] new_node

---------- end of freebsd run and complete gprof output --------------

These are the files involved minus the plan9 binaries and objects. Clearly
bsd prefixed names are the freebsd versions, the others are the plan9
versions. I realise this is of little intrinsic value but at this stage,
short of including the source, i want to deflect as many questions as i
can.

manifest :

total 19386
-rw-r--r--  1 mjpc  users     11953 Jun 10 09:53 INFO
-rw-r--r--  1 mjpc  users      1512 Jun 10 01:54 adw.c
-rw-r--r--  1 mjpc  users     14998 Jun 10 01:54 avl.c
-rw-r--r--  1 mjpc  users      3326 Jun 10 02:01 avl.h
-rwxr-xr-x  1 mjpc  users     13207 Jun 10 09:34 bsd_adw
-rw-r--r--  1 mjpc  users      1483 Jun 10 09:33 bsd_adw.c
-rw-r--r--  1 mjpc  users      2404 Jun 10 09:45 bsd_adw.o
-rwxr-xr-x  1 mjpc  users     13648 Jun 10 09:46 bsd_adwp
-rw-r--r--  1 mjpc  users      3582 Jun 10 09:46 bsd_adwp.gmon
-rw-r--r--  1 mjpc  users     14981 Jun 10 09:33 bsd_avl.c
-rw-r--r--  1 mjpc  users      3330 Jun 10 09:30 bsd_avl.h
-rw-r--r--  1 mjpc  users      8612 Jun 10 09:44 bsd_avl.o
-rw-r--r--  1 mjpc  users      9311 Jun 10 09:47 gprof.out
-rw-r--r--  1 mjpc  users     16970 Jun 10 02:00 libavl.a
-rw-r--r--  1 mjpc  users      8938 Jun 10 09:44 libbsd_avl.a
-rw-r--r--  1 mjpc  users       181 Jun 10 01:54 mkfile
-rw-r--r--  1 mjpc  users  19664049 Jun 10 02:06 mtent13.txt
-rw-r--r--  1 mjpc  users      5008 Jun 10 02:09 prof.312
-rw-r--r--  1 mjpc  users      2465 Jun 10 09:38 prof.out
-rw-r--r--  1 mjpc  users       401 Jun 10 01:54 readme

... some diffs to show there's nothing up my sleeves ...

================= diff adw.c bsd_adw.c ======================
9,10c9
< #include <u.h>
< #include <libc.h>
---
 > #include <stdlib.h>
13c12
< #include "avl.h"
---
 > #include "bsd_avl.h"
65c64
<    print("%7d %s\n", p->count, p->word);
---
 >    printf("%7d %s\n", p->count, p->word);
84c83
<          exits("new_word() failed\n");
---
 >          exit(1);

=============== diff avl.h bsd_avl.h ===================
32c32
<    EXIT_FAILURE = -1,
---
 >    //EXIT_FAILURE = -1,
36c36
< typedef unsigned long size_t;
---
 > //typedef unsigned long size_t;

================ diff avl.c bsd_avl.c ==================
22,24c22,24
< #include <u.h>
< #include <libc.h>
< #include "avl.h"
---
 > #include <stdlib.h>
 > #include <assert.h>
 > #include "bsd_avl.h"
38c38
<       exits("virtual memory exhausted\n");
---
 >       exit(1);

==================== ADDITIONAL NOTES ===================
If I send you the source to run tests with you'll need the mtent13.txt
to do a meaningful comparison :

   http://www.ibiblio.org/pub/docs/books/gutenberg/etext02/mtent13.txt

MD5 (mtent13.txt) = 128e28086063b4c2443179da30befc75