(archive 'newLISPer)

November 2, 2007

Macro economics

Filed under: newLISP — newlisper @ 17:53

My previous attempt at writing macros (Rabbit season) for function tracing worked well, but I should have paid a bit more attention to the business of ‘variable capture’. This happens when symbols inside and outside a Lisp macro have the same name. To illustrate, here’s a simple macro, which adds a new looping construct to the language that combines dolist and do-while. A loop variable steps through a list while a condition is true:

(define-macro (dolist-while)

  (letex (var (args 0 0)

    lst (args 0 1)

    cnd (args 0 2)

    body (cons 'begin (1 (args))))

  (let (y)

  (catch (dolist (var lst)

       (if (set 'y cnd) body (throw y)))))))

You call it like this:

(dolist-while (x (sequence 20 0) (> x 10))

  (println {x is } (dec 'x 1)))



;->

x is 19

x is 18

x is 17

x is 16

x is 15

x is 14

x is 13

x is 12

x is 11

x is 10

The problem here is that you can’t use a symbol called y as the loop variable, although you can use x or anything else. Put a (println y) statement in the loop to see why:

(dolist-while (x (sequence 20 0) (> x 10))

    (println {x is } (dec 'x 1))

    (println {y is }  y))

;->



x is 19

y is true

x is 18

y is true

x is 17

y is true

...    

If you try to use y, it won’t work:

(dolist-while (y (sequence 20 0) (> y 10))

  (println {y is } (dec 'y 1)))



;-> 

y is 

value expected in function dec : y

— in fact we know that y appears as a true/nil value, so it can’t be decremented. The problem is that the y is used by the macro, even though it’s in its own let expression.

Luckily in newLISP there’s an easy fix to this problem, and it’s something that I got slightly wrong in the earlier post. What you do is enclose the macro in a context, and make the macro the default ‘function’ in that context:

(context 'dolist-while)  

(define-macro (dolist-while:dolist-while)

      (letex (var (args 0 0)

        lst (args 0 1)

        cnd (args 0 2)

        body (cons 'begin (1 (args))))

      (let (y)

      (catch (dolist (var lst)

           (if (set 'y cnd) body (throw y)))))))

(context MAIN)

This can be used in the same way, but without any problems:

(dolist-while (y (sequence 20 0) (> y 10))

      (println {y is } (dec 'y 1)))

;->    

y is 19

y is 18

y is 17

...

By the way, another way to define this ‘context’ macro is by using the context prefix throughout, instead of switching to the context:

(define-macro (dolist-while:dolist-while)

  (letex (dolist-while:var (args 0 0)

          dolist-while:lst (args 0 1)

          dolist-while:cnd (args 0 2)

          dolist-while:body (cons 'begin (1 (args))))

  (let (dolist-while:y)

  (catch (dolist (dolist-while:var dolist-while:lst)

       (if (set 'dolist-while:y dolist-while:cnd) 

           dolist-while:body 

           (throw dolist-while:y)))))))

But it’s easier to do it with a context switch!

Timing

I tried this ‘redefine the define’ style of macro for something else – a version of define that records the time taken by each function call. Here’s the context:

(context 'timing)

(set 'timings '())

(define (finish)

   (push (list 'finish (now)) timings -1))

(define-macro (timing:timing farg) 

  (set (farg 0) 

    (letex (func   (farg 0) 

            arg    (rest farg) 

            arg-p  (cons 'list 

              (map (fn (x) (if (list? x) (first x) x)) 

                   (rest farg)))

            body   (cons 'begin (args))) 

           (lambda arg 

             (push (list 'func (now)) timings -1)

            body    ; body of function

            ))))



(context MAIN)

(constant (global 'newLISP-define) define)

(constant (global 'define) timing)

To run a script with this simple timing system, you load the context before you run:

(load {timing.lsp})

then stop timing at the end with

(timing:finish)

After that, the list (timing:timings) contains a record of your script’s functions, with the time when each function was started.

(MAIN:generate-html (2007 11 1 9 43 0 349070 305 5 0 0)) 

(MAIN:div-header (2007 11 1 9 43 0 349291 305 5 0 0)) 

(MAIN:div-header-content (2007 11 1 9 43 0 349310 305 5 0 0)) 

(MAIN:div-left (2007 11 1 9 43 0 349364 305 5 0 0)) 

(MAIN:list-posts-by-title (2007 11 1 9 43 0 349381 305 5 0 0)) 

(MAIN:select-query (2007 11 1 9 43 0 349398 305 5 0 0)) 

(MAIN:list-most-commented-posts (2007 11 1 9 43 0 354983 305 5 0 0)) 

(MAIN:list-most-fetched-posts (2007 11 1 9 43 0 371015 305 5 0 0)) 

...

(MAIN:show-badges (2007 11 1 9 43 0 407344 305 5 0 0)) 

(MAIN:div-footer (2007 11 1 9 43 0 407409 305 5 0 0)) 

(MAIN:div-footer-content (2007 11 1 9 43 0 407426 305 5 0 0)) 

(MAIN:finish (2007 11 1 9 43 0 407499 305 5 0 0))))

(This is a list produced by a run of the index.cgi script that builds this web page.) I tried to make the extra code inserted into each function as small as possible – (push (list 'func (now)) timings -1) seemed pretty minimal. I think (now) is the only newLISP function that can produce microsecond timings – and perhaps they’re not precise to the microsecond either.

Now that you’ve got this list, analysis is easy. You’ll probably want to produce a list of durations:

(define (now-list-to-seconds now-list)

  ; convert minutes/seconds/microseconds of a 

  ; (now)-generated list to microseconds

  (apply add 

    (map mul '(3600000000 60000000 1) (select now-list 4 5 6))))



(define (make-interval t-list)

  ; the list must be sorted into time order, with earliest first

  (sort t-list (fn (x y) (< (last x) (last y))))

  ; add duration

  (dotimes (i (length t-list))

    (set 's (now-list-to-seconds (last (t-list i))))

    (set 'e (now-list-to-seconds (last (t-list (+ i 1)))))

    (push (list (first (t-list i)) (sub e s)) results -1))

  results)

to produce this data, still in evaluation rather than duration order, but showing something akin to duration time for each function call, in microseconds:

((MAIN:generate-html 221) 

 (MAIN:div-header 19) 

 (MAIN:div-header-content 54) 

 (MAIN:div-left 17) 

 (MAIN:list-posts-by-title 17) 

 (MAIN:select-query 5585) 

 (MAIN:list-most-commented-posts 16032) 

 (MAIN:list-most-fetched-posts 4079) 

 (MAIN:list-most-recent-comments 17505) 

 (MAIN:div-center 24) 

 (MAIN:search-posts 32) 

 (MAIN:select-query 7901) 

 (MAIN:search-comments 16) 

 (MAIN:select-query 6510) 

 ...

Already I can see that the functions that take longest are the ones that run a complex SQLite query and format the results.

A list of the most frequently called functions is easy too:

(sort 

   (unique 

      (map (fn (x) 

        (list x (count (list x) (first (transpose data)))))

        (first (transpose data))))

(fn (a b) (> (last a) (last b))))



;->

((select-query (3)) 

 (div-footer-content (1)) 

 (div-footer (1))

 (show-badges (1))

 ...

Only a few more lines (not shown here) are required to produce a list of functions organized by the percentage of the total evaluation time they occupy:

34.22%   MAIN:select-query

29.96%   MAIN:list-most-recent-comments 

27.44%   MAIN:list-most-commented-posts 

 6.98%   MAIN:list-most-fetched-posts

 0.38%   MAIN:generate-html

 0.12%   MAIN:div-footer-content

 0.11%   MAIN:show-badges

 0.10%   MAIN:show-search-form

 0.09%   MAIN:div-header-content

...

The function that runs for the most time is select-query. That’s the main interface to the SQLite library, so if I wanted to make the script run faster, I might start by looking at this function, and the other two query/format functions, to see if I could tighten up the code.

Obviously, all this should be taken very much as a rough guide rather than a precise audit. For one thing, I’m not sure that the microseconds returned by now are as precise as they look. More seriously, running the same script repeatedly shows enough variation to indicate that much depends on what else the computer’s doing at that moment.

Another problem is that the time intervals are measuring elapsed real time, rather than allocated CPU time. Still, the data could provide some clues for further investigation.

Comment from don Lucio

Using newLISP to write a profiler for newLISP programs :-), meta programming is, where Lisp really shines.

Advertisements

Leave a Comment »

No comments yet.

RSS feed for comments on this post.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Blog at WordPress.com.

%d bloggers like this: