Timing Evaluation

Summary: There are many times in which it is useful to find out how long Scheme takes to evaluate an expression. In this reading, we explore DrScheme's `time` procedure, which allows us to time the execution of an operation.

Contents:

Introduction

As you spend more and more time with Scheme (and with algorithm design in general), you'll find that there are many ways to write a solution to the same problem. How do you choose which one is best? Often, the fastest one is the best.

In DrScheme, you can find out how long it takes to evaluate an expression by using `(time expression)`. This operation prints three values, all of which are measured in milliseconds,

• the CPU time for evaluation (how much of the computer's central processing unit the evalutation took);
• the real time for evaluation (how long the operation took based on wall clock time; this time should be longer than CPU time since the computer may be doing other things than evaluting the expression for you); and
• the garbage collection time for evaluation (how much time the computer spent cleaning up all the cons cells and such that get created during the computation).

It also prints out the value of the expression.

For example,

```> (time (slowproc 20))
cpu time: 2990 real time: 3075 gc time: 0
0
```

Plotting Results

Many procedures take differing time depending on the size of the input (e.g., the length of a list if you're recursing over lists or the first number you use if you're recursivng over numbers). To predict how long a procedure will take, we may run it on a variety of size inputs and try to interpolate the curve.

For example, here's a silly procedure that computes the value `0` in a large number of steps.

```(define slowproc
(lambda (n)
(if (< n 1) 0
(+ (slowproc (- n 1))
(slowproc (- n 1))))))
```

Let's look at some examples of how long `slowproc` takes.

```> (time (slowproc 10))
cpu time: 10 real time: 3 gc time: 0
0
> (time (slowproc 15))
cpu time: 100 real time: 123 gc time: 0
0
> (time (slowproc 16))
cpu time: 190 real time: 220 gc time: 0
0
> (time (slowproc 17))
cpu time: 370 real time: 420 gc time: 0
0
> (time (slowproc 18))
cpu time: 750 real time: 793 gc time: 0
0
> (time (slowproc 19))
cpu time: 1500 real time: 1577 gc time: 0
0
```

As you might expect from looking at the code, each time we increase the parameter by one, we approximately double the running time. This procedure is not a good one to use.

Ignoring Results

When you're plotting the amount of time a procedure takes, you often care more about the time than the results of the procedure. If the procedure generates a lot of output, it can get in the way of the time. For example,

```> (time (factorial 1000))
cpu time: 30 real time: 30 gc time: 30
40238726007709377354370243392300398571937486421071463254379991
04299385123986290205920442084869694048004799886101971960586316
66872994808558901323829669944590997424504087073759918823627727
18873251977950595099527612087497546249704360141827809464649629
10563938874378864873371191810458257836478499770124766328898359
55735432513185323958463075557409114262417474349347553428646576
61166779739666882029120737914385371958824980812686783837455973
17461360853795345242215865932019280908782973084313928444032812
31558611036976801357304216168747609675871348312025478589320767
16913244842623613141250878020800026168315102734182797770478463
58681701643650241536913982812648102130927612448963599287051149
64975419909342221566832572080821333186116811553615836546984046
70897560290095053761647584772842188967964624494516076535340819
89013854424879849599533191017233555566021394503997362807501378
37615307127761926849034352625200015888535147331611702103968175
92151090778801939317811419454525722386554146106289218796022383
89714760885062768629671466746975629112340824392081601537808898
93964518263243671616762179168909779911903754031274622289988005
19544441428201218736174599264295658174662830295557029902432415
31816172104658320367869061172601587835207515162842255402651704
83304226143974286933061690897968482590125458327168226458066526
76995865268227280707578139185817888965220816434834482599326604
33676601769996128318607883861502794659551311565520360939881806
12138558600301435694527224206344631797460594682573103790084024
43243846565724501440282188525247093519062092902313649327349756
55139587205596542287497740114133469627154228458623773875382304
83865688976461927383814900140767310446640259899490222221765904
33990188601856652648506179970235619389701786004081188972991831
10211712298459016419210688843871218556461249607987229085192968
19372388642614839657382291123125024186649353143970137428531926
64987533721894069428143411852015801412334482801505139969429015
34830776445690990731524332782882698646027898643211390835062170
95002597389863554277196742822248757586765752344220207573630569
49882508796892816275384886339690995982628095612145099487170124
45164612603790293091208890869420285106401821543994571568059418
72748998094254742173582401063677404595741785160829230135358081
84009699637252423056085590370062427124341690900415369010593398
38357779394109700277534720000000000000000000000000000000000000
00000000000000000000000000000000000000000000000000000000000000
00000000000000000000000000000000000000000000000000000000000000
00000000000000000000000000000000000000000000000000000000000000
00000000000000000000000000
```

If you care only about the time it takes, you can write

```> (define junk (time expression))
```

That command sets `junk` the value of expression and prints out the time it took to compute as a side-effect. For example,

```> (define junk (time (factorial 1000)))
cpu time: 20 real time: 20 gc time: 10
```

History

Monday, 14 April 2003 [Samuel A. Rebelsky]

• Created.

Disclaimer: I usually create these pages on the fly, which means that I rarely proofread them and they may contain bad grammar and incorrect details. It also means that I tend to update them regularly (see the history for more details). Feel free to contact me with any suggestions for changes.

This document was generated by Siteweaver on Tue Dec 9 14:00:33 2003.
The source to the document was last modified on Mon Sep 1 13:26:33 2003.
This document may be found at `http://www.cs.grinnell.edu/~rebelsky/Courses/CS151/2003F/Readings/timing.html`.

You may wish to validate this document's HTML ; ; Check with Bobby

Samuel A. Rebelsky, rebelsky@grinnell.edu