Why does it take so long to print "\n" in Perl?

Question

Why does it take so long to print a newline? Is this just my machine, or do others see the same effect?

With the newline:

#!/usr/bin/perl

use strict;
use Benchmark;

   timethis(100000,'main();');


   sub main {
      print "you are the bomb. \n";
   }


   # outputs: 
   # timethis 100000:  8 wallclock secs ( 0.15 usr +  0.45 sys =  0.60 CPU) @ 166666.67/s (n=100000)

W/o the newline:

#!/usr/bin/perl

use strict;
use Benchmark;

   timethis(100000,'main();');


   sub main {
      print "you are the bomb. ";
   }


   # outputs:
   # timethis 100000:  0 wallclock secs ( 0.09 usr +  0.04 sys =  0.13 CPU) @ 769230.77/s (n=100000)
   #     (warning: too few iterations for a reliable count)

Edit: I'd like to add that placing two "\n" causes the execution to take twice as long, at least for wallclock seconds.

timethis 100000: 16 wallclock secs ( 0.15 usr +  0.52 sys =  0.67 CPU) @ 149253.73/s (n=100000)

Answer 1

I don't think buffering has much to do with it. I'm guessing it's because the terminal needs to scroll when you print a newline to it (or print enough characters to fill a line). When I benchmark these functions writing to a file or to /dev/null, there is not much of a difference.

use Benchmark;
timethis(1000000, 'main');
timethis(1000000, 'main2');
select STDERR; $| = 0; select STDOUT;  # enable buffering on STDERR
sub main { print STDERR "you are the bomb. \n" }
sub main2 { print STDERR "you are the bomb. " }

$ perl benchmark.pl 2> a_file
timethis 1000000: 21 wallclock secs ( 4.67 usr + 13.38 sys = 18.05 CPU) @ 55410.87/s
timethis 1000000: 21 wallclock secs ( 4.91 usr + 13.34 sys = 18.25 CPU) @ 54797.52/s

$ perl benchmark.pl 2> /dev/null
timethis 1000000: 26 wallclock secs ( 2.86 usr + 10.36 sys = 13.22 CPU) @ 75648.69/s
timethis 1000000: 27 wallclock secs ( 2.86 usr + 10.30 sys = 13.16 CPU) @ 76010.95/s

$ perl benchmark.pl 2> a_file     (without buffering)
timethis 1000000: 29 wallclock secs ( 3.78 usr + 12.14 sys = 15.92 CPU) @ 62806.18/s
timethis 1000000: 29 wallclock secs ( 3.27 usr + 12.51 sys = 15.78 CPU) @ 63367.34/s

$ perl benchmark.pl 2> /dev/tty   (window has 35 lines and buffers 10000, YMMV)
[ 200000 declarations of how you are a bomb deleted ]
timethis 100000: 53 wallclock secs ( 0.98 usr +  3.73 sys =  4.72 CPU) @ 21190.93/s
timethis 100000:  9 wallclock secs ( 0.36 usr +  1.94 sys =  2.30 CPU) @ 43535.05/s

Summary: extra flushing reduces performance by about 10%. Extra scrolling on the terminal reduces performance by about 50%.