Quick Tip #24: How long did that take?

I can use P6’s phasers to track how my program moves from one phase to the next. In particular, I’m curious about how much time my program spends in the compile-phase. P6 might be a bit slow now, or at least slower than you think it should be, but that’s okay. The core developers want to be correct first and fast second (but, also both). If you look at the Rakudo change logs, you see lots of entries mentioning big speedups in things they got working first and are now optimizing.

Here I use BEGIN and INIT, although I leave off their braces. In the first put I concatenate a result with its label. In the second put, I interpolate a result into a string by placing code in braces in the string:

put "Compile to run time: " ~ INIT now - BEGIN now;
sleep 3;
put "Run time to finish: { now - INIT now }";

I see that the compile time isn’t that bad (it’s not humanly noticeable in this program):

Compile to run time: 0.03161371
Run time to finish: 3.00564300

You might think its weird that those numbers come out like that when it looks like some things happen earlier than the statement that creates them. I can expand the example to see that the phasers fire before the statements that contain them:

INIT { put "Starting run time at { now }" }
END  { put "Ending at { now }" }

put "Compile to run time: " ~
	INIT { put "INIT in run time message { now }"; now } \ # unspace!
		-
	BEGIN { put "BEGIN in run time message { now }"; now }
	;
sleep 3;
put "Run time to finish: {
	now - INIT { put "INIT in finish message { now }"; now }
	}";

You can see that now creates an Instant object:

BEGIN in run time message Instant:1481307679.940645
Starting run time at Instant:1481307679.995588
INIT in run time message Instant:1481307679.996641
INIT in finish message Instant:1481307679.998188
Compile to run time: 0.0538441
Run time to finish: 3.0023635
Ending at Instant:1481307683.004673

I wanted to check how much of a hit I take by loading a Perl 5 module:

use Business::ISBN:from<Perl5>;

my $isbn = Business::ISBN.new( '9781491954324' );
put "ISBN: ", $isbn.as_string;

put "Compile to run time: " ~ INIT now - BEGIN now;
sleep 3;
put "Run time to finish: { now - INIT now }";

The results are much better than I thought. Even loading a file from a foreign language is quick. It’s not even noticeable:

ISBN: 978-1-4919-5432-4
Compile to run time: 0.0359533
Run time to finish: 3.0084209

If I loaded a different, more complicated module these result may be different. But, I was interested if there was a penalty for loading any module. I don’t see it.

Leave a Reply

Your email address will not be published. Required fields are marked *