[racket] Performance difference write, display, print and pretty-print

At Sat, 25 Aug 2012 22:04:58 -0400, Harry Spier wrote:
> I pretty-printed a data structure to a file to analyse it, and it
> seemed to take a long time to print so I did a timing comparison
> between write, display, print and pretty-print using the same data
> which was a vector of lists of structs. The structs were small  4
> numbers and two very short lists (2 or 3 members).   There were about
> 27000 lines  in the pretty-printed file.
> 
> The timing results for write, display, print and pretty-print this
> data structure was:
> write         cpu time: 188 real time: 232 gc time: 0
> display      cpu time: 328 real time: 324 gc time: 78
> print          cpu time: 10593 real time: 10585 gc time: 218
> pretty-print cpu time: 15288 real time: 15687 gc time: 547
> 
> Why this big difference between the performance of write and display
> to print and pretty-print.  The performance difference (cpu time)
> between write and pretty-print is 82 to 1.

I get similar results for the program below, running in plain Racket
v5.3:

 write:   cpu time: 58 real time: 59 gc time: 0
 display: cpu time: 45 real time: 49 gc time: 0
 print:   cpu time: 61 real time: 64 gc time: 0
 pretty1: cpu time: 4024 real time: 4027 gc time: 15
 pretty:  cpu time: 6050 real time: 6063 gc time: 42

The "pretty1" case uses `pretty-print' with an infinitely wide line,
which corresponds to `print' when running in DrRacket.

So, it looks like about 2.0 seconds of the difference between `write'
and `pretty-print' is then the main work of `pretty-print', which is to
decide where to put line breaks. Maybe that could be faster, but the
interesting question to me was where the other 4.0 seconds go.

The `pretty-print' function uses port-wrapping functions from
`racket/port' that, it turns out, were effectively disabling buffering
for the target file port. I've changed those functions to preserve
buffering, and that was responsible for about 2.5 seconds of the
difference. I get these times for the current Racket pre-release:

 write:   cpu time: 55 real time: 56 gc time: 0
 display: cpu time: 50 real time: 55 gc time: 0
 print:   cpu time: 76 real time: 80 gc time: 15
 pretty1: cpu time: 1472 real time: 1475 gc time: 16
 pretty:  cpu time: 3564 real time: 3577 gc time: 25