From fea1350790f7ffdebcc92527056ceefa70935617 Mon Sep 17 00:00:00 2001
From: Phil Dawes <phil@phildawes.net>
Date: Tue, 8 Jul 2008 20:01:28 +0100
Subject: [PATCH 1/4] Wordtimer vocab for time-profiling words and vocabs
---
extra/wordtimer/authors.txt | 1 +
extra/wordtimer/summary.txt | 1 +
extra/wordtimer/wordtimer-docs.factor | 34 +++++++++++
extra/wordtimer/wordtimer-tests.factor | 10 ++++
extra/wordtimer/wordtimer.factor | 81 ++++++++++++++++++++++++++
5 files changed, 127 insertions(+)
create mode 100644 extra/wordtimer/authors.txt
create mode 100644 extra/wordtimer/summary.txt
create mode 100644 extra/wordtimer/wordtimer-docs.factor
create mode 100644 extra/wordtimer/wordtimer-tests.factor
create mode 100644 extra/wordtimer/wordtimer.factor
diff --git a/extra/wordtimer/authors.txt b/extra/wordtimer/authors.txt
new file mode 100644
index 0000000000..0be42b2faa
--- /dev/null
+++ b/extra/wordtimer/authors.txt
@@ -0,0 +1 @@
+Phil Dawes
diff --git a/extra/wordtimer/summary.txt b/extra/wordtimer/summary.txt
new file mode 100644
index 0000000000..efe591da27
--- /dev/null
+++ b/extra/wordtimer/summary.txt
@@ -0,0 +1 @@
+Microsecond precision code timer/profiler.
diff --git a/extra/wordtimer/wordtimer-docs.factor b/extra/wordtimer/wordtimer-docs.factor
new file mode 100644
index 0000000000..7d9de34252
--- /dev/null
+++ b/extra/wordtimer/wordtimer-docs.factor
@@ -0,0 +1,34 @@
+USING: help.syntax help.markup kernel prettyprint sequences ;
+IN: wordtimer
+
+HELP: reset-word-timer
+{ $description "resets the global wordtimes datastructure. Must be called before calling any word-timer annotated code"
+} ;
+
+HELP: add-timer
+{ $values { "word" "a word" } }
+{ $description "annotates the word with timing code which stores timing information globally. You can then view the info with print-word-timings"
+} ;
+
+HELP: add-timers
+{ $values { "vocab" "a string" } }
+{ $description "annotates all the words in the vocab with timer code. After profiling you can remove the annotations with reset-vocab"
+} ;
+
+
+HELP: reset-vocab
+{ $values { "vocab" "a string" } }
+{ $description "removes the annotations from all the words in the vocab"
+} ;
+
+HELP: print-word-timings
+{ $description "Displays the timing information for each word-timer annotated word. Columns are: total time taken in microseconds, number of invocations, wordname"
+} ;
+
+HELP: correct-for-timing-overhead
+{ $description "attempts to correct the timings to take into account the overhead of the timing function. This is pretty error-prone but can be handy when you're timing words that only take a handful of milliseconds but are called a lot" } ;
+
+ARTICLE: "wordtimer" "Word Timer"
+"The " { $vocab-link "wordtimer" } " vocabulary measures accumulated execution time for words. You first annotate individual words with the " { $link add-timer } " word or whole vocabularies with " { $link add-timers } ". Then you reset the clock with " { $link reset-word-timer } " and execute your code. Finally you can view the timings with " { $link print-word-timings } ". If you have functions that are quick and called often you may want to " { $link correct-for-timing-overhead } ". To remove all the annotations in the vocab you can use " { $link reset-vocab } "." ;
+
+ABOUT: "wordtimer"
diff --git a/extra/wordtimer/wordtimer-tests.factor b/extra/wordtimer/wordtimer-tests.factor
new file mode 100644
index 0000000000..47287179ce
--- /dev/null
+++ b/extra/wordtimer/wordtimer-tests.factor
@@ -0,0 +1,10 @@
+USING: tools.test wordtimer math kernel tools.annotations prettyprint ;
+IN: wordtimer.tests
+
+: testfn ( a b c d -- a+b c+d )
+ + [ + ] dip ;
+
+[ 3 7 ]
+[ reset-word-timer
+ \ testfn [ reset ] [ add-timer ] bi
+ 1 2 3 4 testfn ] unit-test
\ No newline at end of file
diff --git a/extra/wordtimer/wordtimer.factor b/extra/wordtimer/wordtimer.factor
new file mode 100644
index 0000000000..1ce5f13a81
--- /dev/null
+++ b/extra/wordtimer/wordtimer.factor
@@ -0,0 +1,81 @@
+USING: kernel sequences namespaces math assocs words arrays tools.annotations vocabs sorting prettyprint io micros math.statistics ;
+IN: wordtimer
+
+SYMBOL: *wordtimes*
+SYMBOL: *calling*
+
+: reset-word-timer ( -- )
+ H{ } clone *wordtimes* set-global
+ H{ } clone *calling* set-global ;
+
+: lookup-word-time ( wordname -- utime n )
+ *wordtimes* get-global [ drop { 0 0 } ] cache first2 ;
+
+: update-times ( utime current-utime current-numinvokes -- utime' invokes' )
+ rot [ + ] curry [ 1+ ] bi* ;
+
+: register-time ( utime word -- )
+ word-name
+ [ lookup-word-time update-times 2array ] keep *wordtimes* get-global set-at ;
+
+: calling ( word -- )
+ dup *calling* get-global set-at ; inline
+
+: finished ( word -- )
+ *calling* get-global delete-at ; inline
+
+: called-recursively? ( word -- t/f )
+ *calling* get-global at ; inline
+
+: timed-call ( quot word -- )
+ [ calling ] [ >r micro-time r> register-time ] [ finished ] tri ; inline
+
+: time-unless-recursing ( quot word -- )
+ dup called-recursively? not
+ [ timed-call ] [ drop call ] if ; inline
+
+: (add-timer) ( word quot -- quot' )
+ [ swap time-unless-recursing ] 2curry ;
+
+: add-timer ( word -- )
+ dup [ (add-timer) ] annotate ;
+
+: add-timers ( vocabspec -- )
+ words [ add-timer ] each ;
+
+: reset-vocab ( vocabspec -- )
+ words [ reset ] each ;
+
+: dummy-word ( -- ) ;
+
+: time-dummy-word ( -- n )
+ [ 100000 [ [ dummy-word ] micro-time , ] times ] { } make median ;
+
+: subtract-overhead ( {oldtime,n} overhead -- {newtime,n} )
+ [ first2 ] dip
+ swap [ * - ] keep 2array ;
+
+: change-global ( variable quot -- )
+ global swap change-at ;
+
+: (correct-for-timing-overhead) ( timingshash -- timingshash )
+ time-dummy-word [ subtract-overhead ] curry assoc-map ;
+
+: correct-for-timing-overhead ( -- )
+ *wordtimes* [ (correct-for-timing-overhead) ] change-global ;
+
+: print-word-timings ( -- )
+ *wordtimes* get-global [ swap suffix ] { } assoc>map natural-sort reverse pprint ;
+
+
+: profile-vocab ( vocabspec quot -- )
+ "annotating vocab..." print flush
+ over [ reset-vocab ] [ add-timers ] bi
+ reset-word-timer
+ "executing quotation..." print flush
+ [ call ] micro-time >r
+ "resetting annotations..." print flush
+ swap reset-vocab
+ correct-for-timing-overhead
+ "total time:" write r> pprint
+ print-word-timings ;
\ No newline at end of file
From f485c63f22cb1f21eaee5b7ed39d11b203e5a86b Mon Sep 17 00:00:00 2001
From: Phil Dawes <phil@phildawes.net>
Date: Tue, 8 Jul 2008 20:32:34 +0100
Subject: [PATCH 2/4] fixed to use new-style accessor for word-name
---
extra/wordtimer/wordtimer.factor | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/extra/wordtimer/wordtimer.factor b/extra/wordtimer/wordtimer.factor
index 1ce5f13a81..e9ed0c8cf0 100644
--- a/extra/wordtimer/wordtimer.factor
+++ b/extra/wordtimer/wordtimer.factor
@@ -1,4 +1,4 @@
-USING: kernel sequences namespaces math assocs words arrays tools.annotations vocabs sorting prettyprint io micros math.statistics ;
+USING: kernel sequences namespaces math assocs words arrays tools.annotations vocabs sorting prettyprint io micros math.statistics accessors ;
IN: wordtimer
SYMBOL: *wordtimes*
@@ -15,7 +15,7 @@ SYMBOL: *calling*
rot [ + ] curry [ 1+ ] bi* ;
: register-time ( utime word -- )
- word-name
+ name>>
[ lookup-word-time update-times 2array ] keep *wordtimes* get-global set-at ;
: calling ( word -- )
From 8e24fb9e051e69af1a88edb476605273df84ab9e Mon Sep 17 00:00:00 2001
From: Phil Dawes <phil@phildawes.net>
Date: Tue, 8 Jul 2008 20:50:49 +0100
Subject: [PATCH 3/4] Added doc for profile-vocab
---
extra/wordtimer/wordtimer-docs.factor | 9 ++++++++-
1 file changed, 8 insertions(+), 1 deletion(-)
diff --git a/extra/wordtimer/wordtimer-docs.factor b/extra/wordtimer/wordtimer-docs.factor
index 7d9de34252..47b85bb007 100644
--- a/extra/wordtimer/wordtimer-docs.factor
+++ b/extra/wordtimer/wordtimer-docs.factor
@@ -27,8 +27,15 @@ HELP: print-word-timings
HELP: correct-for-timing-overhead
{ $description "attempts to correct the timings to take into account the overhead of the timing function. This is pretty error-prone but can be handy when you're timing words that only take a handful of milliseconds but are called a lot" } ;
+
+HELP: profile-vocab
+{ $values { "vocabspec" "string name of a vocab" }
+ { "quot" "a quotation to run" } }
+{ $description "Annotates the words in the vocab with timing code then runs the quotation. Finally resets the words and prints the timings information."
+} ;
+
ARTICLE: "wordtimer" "Word Timer"
-"The " { $vocab-link "wordtimer" } " vocabulary measures accumulated execution time for words. You first annotate individual words with the " { $link add-timer } " word or whole vocabularies with " { $link add-timers } ". Then you reset the clock with " { $link reset-word-timer } " and execute your code. Finally you can view the timings with " { $link print-word-timings } ". If you have functions that are quick and called often you may want to " { $link correct-for-timing-overhead } ". To remove all the annotations in the vocab you can use " { $link reset-vocab } "." ;
+"The " { $vocab-link "wordtimer" } " vocabulary measures accumulated execution time for words. If you just want to profile the accumulated time taken by all words in a vocab you can use " { $vocab-link "profile-vocab" } ". If you need more fine grained control then do the following: First annotate individual words with the " { $link add-timer } " word or whole vocabularies with " { $link add-timers } ". Then reset the clock with " { $link reset-word-timer } " and execute your code. Finally you can view the timings with " { $link print-word-timings } ". If you have functions that are quick and called often you may want to " { $link correct-for-timing-overhead } ". To remove all the annotations in the vocab you can use " { $link reset-vocab } ". Alternatively if you just want to time the contents of a vocabulary you can use profile-vocab." ;
ABOUT: "wordtimer"
From e3ce229c1f52de65730abcea66ad5a1811042945 Mon Sep 17 00:00:00 2001
From: Alfredo Beaumont <alfredo.beaumont@gmail.com>
Date: Thu, 10 Jul 2008 23:55:45 +0200
Subject: [PATCH 4/4] Fix a stack underflow
---
extra/wordtimer/wordtimer.factor | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/extra/wordtimer/wordtimer.factor b/extra/wordtimer/wordtimer.factor
index e9ed0c8cf0..5da17e28d5 100644
--- a/extra/wordtimer/wordtimer.factor
+++ b/extra/wordtimer/wordtimer.factor
@@ -75,7 +75,7 @@ SYMBOL: *calling*
"executing quotation..." print flush
[ call ] micro-time >r
"resetting annotations..." print flush
- swap reset-vocab
+ reset-vocab
correct-for-timing-overhead
"total time:" write r> pprint
print-word-timings ;
\ No newline at end of file