[Top][All Lists]
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
address@hidden: Re: [Gcl-devel] Re: Profiling [ was Re: lisp reader enha
|
From: |
Matt Kaufmann |
|
Subject: |
address@hidden: Re: [Gcl-devel] Re: Profiling [ was Re: lisp reader enhancement ]] |
|
Date: |
Mon, 11 Aug 2003 15:05:59 -0500 |
Camm --
OOPS -- my apologies! I just noticed that the environment had changed when I
ran the test below, and I need to do some recompilation. So never mind about
the error, although I'm still interested in whether I called the
profiling-related functions correctly.
Thanks --
-- Matt
------- Start of forwarded message -------
Date: 11 Aug 2003 15:02:46 -0500
From: Matt Kaufmann <address@hidden>
To: address@hidden
CC: address@hidden
In-reply-to: <address@hidden> (address@hidden)
Subject: Re: [Gcl-devel] Re: Profiling [ was Re: lisp reader enhancement
]
Hi, Camm --
After rebuilding ACL2 on GCL,
OK, we've rebuilt GCL, including (I believe) all patches you've sent, and I've
built ACL2 on top of it and tried the test again. But I got an error, as
explained below. Below I'll tell you what I did and then what the error was.
You said the following:
b) run si::prof with the starting address you desire to
examine, and a 'scale' parameter indicating how many counter
profile array elements to allocate to each 256 bytes of code.
You can see these addresses reported on loading binary
modules, or you could use the DBEGIN value issued at configure
time. You could also try function-address. We need to make
it easier to just say 'profile my whole program', but what I
did was find the address of _init in gdb, find the value of
heap_end in gdb, figure out a good scale for this amount of
memory to correspond to a 1000000 byte array, and issue the
following call for maxima:
:lisp (si::prof 134522412 15)
I did the following, which seemed to give me _init and heap_end:
[ 202 ] --> gdb gcl-saved_acl2
GNU gdb 5.3
Copyright 2002 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "i686-pc-linux-gnu"...
(gdb) p _init
$1 = {<text variable, no debug info>} 0x8049cb0 <_init>
(gdb) p heap_end
$2 = 154292224
(gdb)
I think you're saying that the second argument to si::prof should be computed
as shown below:
>(/ (- 154292224 #x8049cb0) 1000000.0)
;heap_end ;_init
19.77224
So I did this:
(si::set-up-profile 1000000 8000) ; ACL2 has about 4100 defuns and about 600
macros
(si::prof #x8049cb0 20)
After executing the forms above before starting on the "real" computation, I
ran into this problem, which I don't think I've seen before:
%%AND-TREE
[SGC for 3000 CONS pages..(10580 writable)..(T=19).GC finished]
[SGC for 3000 CONS pages..(10609 writable)..(T=19).GC finished]
[SGC for 3000 CONS pages..(10624 writable)..(T=20).GC finished]
[SGC for 232 FIXNUM pages..(10625 writable)..(T=22).GC finished]
[SGC for 232 FIXNUM pages..(10626 writable)..(T=22).GC finished]
[SGC for 232 FIXNUM pages..(10627 writable)..(T=21).GC finished]
[SGC for 3000 CONS pages..(10632 writable)..(T=21).GC finished]
[SGC off][GC for 750 RELOCATABLE-BLOCKS pages..(T=66).GC finished]
[SGC on][SGC off][GC for 750 RELOCATABLE-BLOCKS pages..(T=70).GC finished]
[SGC on][SGC off][GC for 750 RELOCATABLE-BLOCKS pages..(T=73).GC finished]
[SGC on][SGC for 3043 CONS pages..(7025 writable)..(T=11).GC finished]
[SGC for 0 RELOCATABLE-BLOCKS pages..(7091 writable)..(T=10).GC finished]
[SGC for 3043 CONS pages..(7820 writable)..(T=13).GC finished]
Error: Frame stack overflow.
Fast links are on: do (si::use-fast-links nil) for debugging
Error signalled by IF.
Broken at COND. Type :H for Help.
ACL2>>
Any suggestions?
- -- Matt
cc: address@hidden, address@hidden
From: "Camm Maguire" <address@hidden>
Date: 05 Aug 2003 16:22:12 -0400
User-Agent: Gnus/5.09 (Gnus v5.9.0) Emacs/21.2
X-WSS-ID: 132ECD8D9243291-01-01
Content-Type: text/plain;
charset=us-ascii
Hi Matt!
"Matt Kaufmann" <address@hidden> writes:
> Hi, Camm --
>
> I haven't yet rebuilt GCL since your last patch related to profiling --
> actually Rob Sumners has been doing the builds so I'm waiting on him (and
he
> has a lot on his plate at work, though I imagine he may have time soon).
>
OK, please keep me posted. I might accept a small performance hit,
but not 3x :-).
> But, I wanted to let you know I've discovered a bug in the previous reader
> patches that you sent. It's illustrated below (comments added). The
problem
> goes away if (a . b) is replaced by (a b), so I guess this has to do with
> reading dotted pairs.
>
Here is a fix, just checked in:
===================================================================
RCS file: /cvsroot/gcl/gcl/o/read.d,v
retrieving revision 1.17
diff -u -r1.17 read.d
--- read.d 30 Jul 2003 20:26:01 -0000 1.17
+++ read.d 5 Aug 2003 20:18:10 -0000
@@ -663,6 +663,9 @@
c = read_char(in);
if (char_code(c) != ')')
FEerror("A dot appeared before a right parenthesis.", 0);
+ else if (PP0>P0) PP0--; /* should be the only other
place
+ outside of read_object where
+ closing parens are read */
goto ENDUP;
}
vs_push(x);
Take care,
> GCL (GNU Common Lisp) (2.5.3) Mon Jul 21 10:41:19 CDT 2003
> Licensed under GNU Library General Public License
> Dedicated to the memory of W. Schelter
>
> Use (help) to get some basic information on how to use GCL.
>
> >(make-package "ABC" :use nil)
>
> #<"ABC" package>
>
> >(import '(package-name symbol-package) (find-package "ABC"))
>
> T
>
> >(package-name (symbol-package 'xxxx))
>
> "USER"
>
> >*package*
>
> #<"USER" package>
>
> >'abc::((a . b))
>
> ((ABC::A . ABC::B))
>
> >(package-name (symbol-package 'xxxx)) ;;; !!! Here is the first
surprise.
>
> "ABC"
>
> >user::*package* ;;; !!! It's a little surprising that the *package* is
still
> ;;; right, even though the reader isn't using that
> ;;; package.
>
> #<"USER" package>
>
> >
>
> -- Matt
> Resent-From: address@hidden
> Resent-To: address@hidden
> cc: address@hidden
> From: "Camm Maguire" <address@hidden>
> Date: 04 Aug 2003 19:21:07 -0400
> User-Agent: Gnus/5.09 (Gnus v5.9.0) Emacs/21.2
> X-WSS-ID: 133121B59149313-01-01
> Content-Type: text/plain;
> charset=us-ascii
>
> Greetings! Just a followup note here in case you're still interested in
> trying to analyze the performance.
>
> 1) If you reran with the new gbc-time, I'd be interested to know
> what it was.
>
> 2) I've been looking at GCL's two profiling modes. The first is based
> on the 'profil' call to libc. It works, but unfortunately our
> documentation is misleading/wrong. The idea is to:
>
> 0) Apply the following two patches:
>
> ===================================================================
> RCS file: /cvsroot/gcl/gcl/o/fat_string.c,v
> retrieving revision 1.14
> diff -u -r1.14 fat_string.c
> --- fat_string.c 15 Feb 2003 00:38:28 -0000 1.14
> +++ fat_string.c 4 Aug 2003 22:52:09 -0000
> @@ -49,7 +49,7 @@
> if( type_of(start_address)!=t_fixnum || type_of(scale)!=t_fixnum)
> FEerror("Needs start address and scale as args",0);
>
> - profil((void *) (ar->ust.ust_self), (ar->ust.ust_dim),
> + profil(!(fix(start_address)*fix(scale)) ? NULL : (void *)
(ar->ust.ust_self), (ar->ust.ust_dim),
> fix(start_address),fix(scale) << 8);
> RETURN1(start_address);
> }
> --- ptable.h 12 Jul 2002 22:00:48 -0000 1.4
> +++ ptable.h 4 Aug 2003 22:51:56 -0000
> @@ -50,7 +50,7 @@
> #ifdef SPECIAL_RSYM
> struct string_address_table c_table;
> #else
> -static struct bfd_link_info link_info;
> +struct bfd_link_info link_info;
> #endif
> struct string_address_table combined_table;
>
>
> a) in your program, first run set-up-profile, defined in
> profile.lsp (should be in your gcl autoload path). The first
> argument is the size of the profile array, with 1000000 being
> suggested in the docs -- this works for me. What is not
> documented is the optional second argument specifying the
> maximum number of functions in your image. I had to supply
> this to increase the default value when testing in maxima.
> Here is my call:
>
> :lisp (si::set-up-profile 1000000 8000)
>
>
> Loaded c and other function addresses
> Using profile-array length 1000000
> Use (si::prof 0 90) to start and (prof 0 0) to stop:
> This starts monitoring at address 0
> thru byte (256/90)*(length *profile-array*)
> (si::display-prof) displays the results
> NIL
>
> b) run si::prof with the starting address you desire to
> examine, and a 'scale' parameter indicating how many counter
> profile array elements to allocate to each 256 bytes of code.
> You can see these addresses reported on loading binary
> modules, or you could use the DBEGIN value issued at configure
> time. You could also try function-address. We need to make
> it easier to just say 'profile my whole program', but what I
> did was find the address of _init in gdb, find the value of
> heap_end in gdb, figure out a good scale for this amount of
> memory to correspond to a 1000000 byte array, and issue the
> following call for maxima:
>
> :lisp (si::prof 134522412 15)
>
> c) run some intesive code, I did load("tests.lisp");
>
> d) Turn off the profiler
>
> :lisp (si::prof 0 0)
>
> e) display the results, probably using the same scale and
> start address as in b):
>
> :lisp (si::display-profile 134522412 15)
>
> My output follows. There are a few gotchas in interpretation
> -- If a global function in GCL's core is separated from the
> next such function by a bunch of static functions, all counts
> for the static functions get lumped into the first's counter.
> The large values for 'enter_mark_origin' thus refers to the
> GBC time in the marker and sweeper located in between in the
> code. Also needs cleaning up.
>
> All user functions are not thus afflicted. But the core
> function counts are probably illustrative, as they may indicate
> inefficiencies in the lisp compiler's optimization/inlining of
> calls.
>
> I short, I'd appreciate seeing your version of the following:
>
> 0.10% ( 1): strerror
> 0.10% ( 1): memmove
> 0.39% ( 4): IapplyVector
> 0.39% ( 4): Iinvoke_c_function_from_value_stack
> 0.10% ( 1): make_fixnum1
> 0.10% ( 1): pack_hash
> 0.19% ( 2): intern
> 0.10% ( 1): Lintern
> 0.10% ( 1): Lunuse_package
> 0.10% ( 1): Lparse_namestring
> 0.10% ( 1): fLrationalp
> 0.10% ( 1): fLfunctionp
> 1.07% ( 11): eql
> 0.58% ( 6): equal
> 0.29% ( 3): init_predicate_function
> 0.10% ( 1): edit_double
> 0.78% ( 8): write_object
> 0.68% ( 7): Lwrite_char
> 0.10% ( 1): princ
> 0.19% ( 2): init_prog
> 0.58% ( 6): read_object
> 0.39% ( 4): NIL
> 0.19% ( 2): NIL
> 0.87% ( 9): Lread_char
> 0.10% ( 1): rl_putc_em
> 0.48% ( 5): symbol_function
> 0.10% ( 1): Lelt
> 1.55% ( 16): elt
> 0.39% ( 4): elt_set
> 0.87% ( 9): length
> 0.19% ( 2): nreverse
> 0.10% ( 1): fSclear_connection_state
> 0.19% ( 2): coerce_to_string
> 0.10% ( 1): get_string_start_end
> 0.19% ( 2): Lstring_neq
> 0.10% ( 1): Lmake_string
> 0.19% ( 2): Lstring_right_trim
> 0.10% ( 1): structure_ref
> 0.68% ( 7): symbol_value
> 1.84% ( 19): getf
> 0.10% ( 1): get
> 0.19% ( 2): remf
> 0.10% ( 1): remprop
> 0.19% ( 2): Lgetf
> 0.39% ( 4): check_type_symbol
> 0.10% ( 1): check_type_string
> 0.10% ( 1): check_type_cons
> 0.10% ( 1): Ltype_of
> 2.62% ( 27): alloc_object
> 3.30% ( 34): make_cons
> 0.39% ( 4): alloc_relblock
> 0.29% ( 3): fLrow_major_aref
> 0.10% ( 1): fSaset1
> 0.10% ( 1): fSget_aelttype
> 0.19% ( 2): gset
> 0.10% ( 1): array_allocself
> 0.10% ( 1): fLfill_pointer
> 0.48% ( 5): setq
> 0.10% ( 1): fLmakunbound
> 0.10% ( 1): fSset_gmp_allocate_relocatable
> 0.19% ( 2): new_bignum
> 0.10% ( 1): normalize_big_to_object
> 0.10% ( 1): mul_int_big
> 0.39% ( 4): normalize_big
> 0.10% ( 1): big_minus
> 0.19% ( 2): maybe_replace_big
> 0.39% ( 4): integer_quotient_remainder_1
> 0.19% ( 2): parse_key_new_new
> 0.19% ( 2): Lchar_eq
> 0.10% ( 1): Lchar_neq
> 0.10% ( 1): Lchar_upcase
> 0.10% ( 1): cplus
> 0.10% ( 1): init_error
> 1.94% ( 20): funcall
> 0.19% ( 2): funcall_no_event
> 0.10% ( 1): super_funcall
> 0.29% ( 3): super_funcall_no_event
> 0.10% ( 1): readc_stream
> 0.10% ( 1): unreadc_stream
> 0.58% ( 6): writec_stream
> 0.29% ( 3): flush_stream
> 0.39% ( 4): read_fasl_data
> 0.10% ( 1): Lformat
> 0.29% ( 3): fLformat
> 0.10% ( 1): frs_sch_catch
> 0.10% ( 1): call_or_link
> 0.48% ( 5): c_apply_n
> 3.39% ( 35): call_proc_new
> 31.62% ( 326): enter_mark_origin
> 0.10% ( 1): perm_writable
> 1.65% ( 17): car
> 1.65% ( 17): cdr
> 0.29% ( 3): kar
> 1.26% ( 13): list
> 0.19% ( 2): listA
> 0.10% ( 1): append
> 0.19% ( 2): copy_list
> 0.19% ( 2): Lcdr
> 0.10% ( 1): cddr
> 0.39% ( 4): Llast
> 0.39% ( 4): Lmake_list
> 0.10% ( 1): Lrevappend
> 0.29% ( 3): nconc
> 0.10% ( 1): Lreconc
> 0.10% ( 1): fixnum_add
> 0.19% ( 2): number_plus
> 0.19% ( 2): number_minus
> 0.19% ( 2): get_gcd
> 0.97% ( 10): number_compare
> 0.10% ( 1): Lall_the_same
> 0.10% ( 1): number_expt
> 0.10% ( 1): GET-INSTREAM
> 0.29% ( 3): READ-FROM-STRING
> 0.10% ( 1): TYPEP
> 0.10% ( 1): SYSTEM::NORMALIZE-TYPE
> 0.48% ( 5): SYSTEM::KNOWN-TYPE-P
> 0.29% ( 3): SUBTYPEP
> 0.10% ( 1): CONCATENATE
> 0.10% ( 1): SYSTEM::BAD-SEQ-LIMIT
> 0.10% ( 1): REMOVE
> 0.10% ( 1): DELETE
> 0.19% ( 2): POSITION
> 0.10% ( 1): SORT
> 0.10% ( 1): WITH-HASH-TABLE-ITERATOR
> 0.10% ( 1): user_match
> 0.10% ( 1): ASSQR
> 0.10% ( 1): SYS-FREE-MEMORY
> 0.19% ( 2): MGET
> 0.10% ( 1): MACLISP-TYPEP
> 0.19% ( 2): BOTHCASE-IMPLODE
> 0.10% ( 1): LIST-STRING
> 0.10% ( 1): TYO
> 0.39% ( 4): TYI
> 0.10% ( 1): FILE-TO-STRING
> 0.10% ( 1): ALPHALESSP
> 0.78% ( 8): MEMQ
> 0.10% ( 1): DELQ
> 0.29% ( 3): SAFE-GET
> 0.19% ( 2): GETL
> 0.10% ( 1): SUB
> 0.19% ( 2): ASSOL
> 0.10% ( 1): ASSOLIKE
> 0.10% ( 1): MAXIMA-SUBSTITUTE
> 0.19% ( 2): GETOP
> 0.19% ( 2): GETOPR
> 0.10% ( 1): $LISTP
> 0.10% ( 1): SPANG1
> 0.10% ( 1): $GETCHAR
> 0.10% ( 1): MEVALARGS
> 0.10% ( 1): SAFE-MGETL
> 1.36% ( 14): MEVAL1
> 0.10% ( 1): GETL-LM-FCN-PROP
> 0.10% ( 1): MGETL
> 0.10% ( 1): $SQRT
> 0.10% ( 1): $BINOMIAL
> 0.19% ( 2): ONEP1
> 0.39% ( 4): ZEROP1
> 0.19% ( 2): MNUMP
> 0.10% ( 1): RATNUMP
> 0.10% ( 1): MEXPTP
> 0.10% ( 1): $RATNUMP
> 0.10% ( 1): SPECREPCHECK
> 0.10% ( 1): CONSTANT
> 0.10% ( 1): MAXIMA-CONSTANTP
> 0.10% ( 1): MXORLISTP1
> 0.10% ( 1): CONSTFUN
> 0.10% ( 1): FREE
> 0.58% ( 6): SIMPLIFYA
> 0.29% ( 3): EQTEST
> 0.10% ( 1): RULECHK
> 0.10% ( 1): TIMESK
> 0.10% ( 1): PLS
> 0.10% ( 1): TESTT
> 0.10% ( 1): TESTTNEG
> 0.19% ( 2): SIMPTIMES
> 0.10% ( 1): STIMEX
> 0.10% ( 1): TMS
> 0.10% ( 1): SIGNUM1
> 0.19% ( 2): EXPTRL
> 0.10% ( 1): SIMPEXPT
> 0.29% ( 3): TIMESIN
> 0.58% ( 6): ALIKE1
> 0.10% ( 1): ALIKE
> 0.10% ( 1): ORDHACK
> 0.10% ( 1): RATNUMERATOR
> 0.39% ( 4): NTHKDR
> 0.10% ( 1): $MKEY
> 0.10% ( 1): MEVAL*
> 0.10% ( 1): KILL1
> 0.10% ( 1): REMALIAS
> 0.10% ( 1): STRING*
> 0.10% ( 1): $NOUNIFY
> 0.10% ( 1): PFLATTEN
> 0.10% ( 1): PMINUSP
> 0.10% ( 1): PQUOTIENT
> 0.19% ( 2): ALGORD
> 0.10% ( 1): PSIMP
> 0.10% ( 1): PCETIMES1
> 0.10% ( 1): PCTIMES
> 0.10% ( 1): PEXPTSQ
> 0.58% ( 6): $APROPOS
> 0.10% ( 1): DIVISORS
> 0.10% ( 1): COMPLETEVECTOR
> 0.10% ( 1): CFACTOR
> 0.19% ( 2): SAVEFACTORS
> 0.10% ( 1): FACTOROUT1
> 0.10% ( 1): PFACTOR1
> 0.10% ( 1): PSQUOREM1
> 0.10% ( 1): OLDCONTENT1
> 0.10% ( 1): PCONTENTZ
> 0.19% ( 2): $RATSIMP
> 0.10% ( 1): $FACTOR
> 0.10% ( 1): RATSETUP1
> 0.10% ( 1): GENSYM-READABLE
> 0.10% ( 1): ORDERPOINTER
> 0.10% ( 1): RATREP*
> 0.10% ( 1): RATF
> 0.29% ( 3): PREP1
> 0.10% ( 1): NEWVAR1
> 0.10% ( 1): PDISREP
> 0.10% ( 1): PDISREP!
> 0.10% ( 1): PDISREP2
> 0.10% ( 1): $RATDISREP
> 0.10% ( 1): CDISREP
> 0.10% ( 1): NEWVAR
> 0.10% ( 1): RADSORT
> 0.10% ( 1): RDIS*
> 0.10% ( 1): PRODCOEF
> 0.19% ( 2): FREEOF
> 0.10% ( 1): FLGREAT1
> 0.19% ( 2): STRING1
> 0.19% ( 2): MSIZE
> 0.10% ( 1): MSIZE-ATOM
> 0.10% ( 1): MSZ
> 0.10% ( 1): MSZ-MEXPT
> 0.29% ( 3): STRMDOIN
> 0.10% ( 1): NFORMAT
> 0.39% ( 4): FORM-MTIMES
> 0.10% ( 1): IMEMBER
> 0.10% ( 1): ALPHABETP
> 0.10% ( 1): ASCII-NUMBERP
> 0.10% ( 1): TYI-PARSE-INT
> 0.10% ( 1): ALIASLOOKUP
> 0.19% ( 2): GOBBLE-WHITESPACE
> 0.10% ( 1): PARSER-ASSOC
> 0.19% ( 2): READ-COMMAND-TOKEN-AUX
> 0.10% ( 1): READLIST
> 0.19% ( 2): SCAN-DIGITS
> 0.10% ( 1): COLLISION-CHECK
> 0.10% ( 1): MREAD
> 0.29% ( 3): ADD-LINEINFO
> 0.10% ( 1): TRIGINT
> 0.10% ( 1): $LISTOFVARS
> 0.19% ( 2): DIMENSION
> 0.10% ( 1): MAKESTRING
> 0.10% ( 1): DIMENSION-SUPERSCRIPT
> 0.10% ( 1): CHECKFIT
> 0.19% ( 2): CHECKBREAK
> 0.19% ( 2): OUTPUT
> 0.10% ( 1): DRAW-LINEAR
> 0.10% ( 1): D-SUMSIGN
> 0.48% ( 5): EXPLODEN
> 0.10% ( 1): CNTP
> 0.10% ( 1): LEARN
> 0.10% ( 1): LIKE
> 0.10% ( 1): DEQ
> 0.10% ( 1): TESTA*
> 0.10% ( 1): E1-
> 0.10% ( 1): PSTIMES
> 0.19% ( 2): PSEXPT1
> 0.10% ( 1): GET-ARRAY-POINTER
> 0.10% ( 1): SIMPLIM%INVERSE_JACOBI_DS
> 0.10% ( 1): %$ETEST
> Total ticks 1031
> 134522412
>
> f) I'd like suggestions on how to improve the usability here.
>
> 3) The gprof mode will require a bit more work, as recent gprof in
> Linux calls monstartup authmatically in gcrt0.o, foiling the
> existing strategy in the code.
>
> Take care,
>
>
>
> --
> Camm Maguire address@hidden
>
==========================================================================
> "The earth is but one country, and mankind its citizens." --
Baha'u'llah
>
>
>
> _______________________________________________
> Gcl-devel mailing list
> address@hidden
> http://mail.gnu.org/mailman/listinfo/gcl-devel
>
>
>
--
Camm Maguire address@hidden
==========================================================================
"The earth is but one country, and mankind its citizens." -- Baha'u'llah
------- End of forwarded message -------
- address@hidden: Re: [Gcl-devel] Re: Profiling [ was Re: lisp reader enhancement ]],
Matt Kaufmann <=