C[omp]ute

From: andrew cooke <andrew@...>

Date: Wed, 1 Jan 2014 12:51:06 -0300

I've just spent a little less than an hour optimizing some Julia code - I got
a factor of 6 or 7 speedup.

The program is a depth-first search to find the internal state of an RC5
cipher (you can the current code at
https://github.com/andrewcooke/BlockCipherSelfStudy.jl/blob/master/src/RC5.jl#L483
or nearby), so I initially focussed on the inner loop of the encryption.

In an interactive julia session I ran code like:

  include("RC5.jl")
  s = RC5.State(Uint32, 0x6, Uint8[0x0], rotate=false)
  @time (for i in 1:1000; RC5.encrypt(s, 0x12345678, 0x87654321); end)

which printed something like

  elapsed time: 0.000249587 seconds (64000 bytes allocated)

That seemed a little odd - I couldn't see why any memory needed to be
allocated.  It turns out that the tuple returned by the routine needs some
memory.

So I replaced that return with a mutable structure (a "type" in Julia
parlance) passed as an argument, which removed any memory use and gave a
speedup (at the cost of some ugliness).

At this point it wasn't clear what else to do, so I decided to profile.  I
modified the source to look like

  @time key_from_encrypt(1, make_solve_dfs_noro(Uint32, 0x3, 32),
		   fake_keygen(Uint32, 0x3, 0x10, rotate=false),
		   k -> (a, b) -> encrypt(k, a, b),
		   eq=same_ctext(1024, encrypt))
  @time key_from_encrypt(1, make_solve_dfs_noro(Uint32, 0x3, 32),
		   fake_keygen(Uint32, 0x3, 0x10, rotate=false),
		   k -> (a, b) -> encrypt(k, a, b),
		   eq=same_ctext(1024, encrypt))

and ran it from the command line.  The first @time is larger (JIT warming up),
but the second gave a baseline value for the elapsed time.

Then I changed the code to

  @time key_from_encrypt(1, make_solve_dfs_noro(Uint32, 0x3, 32),
		   fake_keygen(Uint32, 0x3, 0x10, rotate=false),
		   k -> (a, b) -> encrypt(k, a, b),
		   eq=same_ctext(1024, encrypt))
  @profile key_from_encrypt(1, make_solve_dfs_noro(Uint32, 0x3, 32),
		   fake_keygen(Uint32, 0x3, 0x10, rotate=false),
		   k -> (a, b) -> encrypt(k, a, b),
		   eq=same_ctext(1024, encrypt))

(note @time -> @profile) and, in an iteractive Julia session, loaded the
module a couple of times.  Once I had done that, running

  Profile.print()

generated a profile like

  julia> Profile.print()
  2   ...erSelfStudy/src/RC5.jl; set_state; line: 472
  1   ...erSelfStudy/src/RC5.jl; test_bits; line: 458
  1   ...erSelfStudy/src/RC5.jl; test_bits; line: 463
       1   no file; anonymous; line: 7
       2   no file; anonymous; line: 8
	  1 task.jl; produce; line: 52
	  1 task.jl; produce; line: 53
       1   no file; anonymous; line: 9
       5   no file; anonymous; line: 25
	  2 task.jl; produce; line: 53
       1   no file; anonymous; line: 26
	 1   no file; anonymous; line: 38
			       461 .../src/RC5.jl; solutions; line: 14
				     456 ...Solve.jl; key_from_encrypt; line: 11
				       8   .../RC5.jl; solve; line: 486
				       1   .../RC5.jl; solve; line: 490
				       1   .../RC5.jl; solve; line: 491
				       190 .../RC5.jl; solve; line: 494
					10 .../RC5.jl; set_state; line: 472
					9  .../RC5.jl; set_state; line: 473
					32 .../RC5.jl; set_state; line: 474
					69 .../RC5.jl; set_state; line: 475
					62 .../RC5.jl; set_state; line: 477
					6  .../RC5.jl; set_state; line: 479
				       14  .../RC5.jl; solve; line: 495
				       225 .../RC5.jl; solve; line: 496
					 1   ...RC5.jl; test_bits; line: 458
					 1   ...RC5.jl; test_bits; line: 463
					  1  ...RC5.jl; encrypt; line: 108
					  1  ...RC5.jl; encrypt; line: 122
					  5  ...RC5.jl; test_bits; line: 456
					  18 ...RC5.jl; test_bits; line: 458
					  6  ...RC5.jl; test_bits; line: 459
					  13 ...RC5.jl; test_bits; line: 460
					  73 ...RC5.jl; test_bits; line: 461
				       +1 6  ...RC5.jl; encrypt; line: 108
				       +1 6  ...RC5.jl; encrypt; line: 109
				       +1 14 ...RC5.jl; encrypt; line: 110
				       +1 2  ...RC5.jl; encrypt; line: 112
				       +1 23 ...RC5.jl; encrypt; line: 115
				       +1 5  ...RC5.jl; encrypt; line: 116
				       +1 1  ...RC5.jl; encrypt; line: 117
				       +1 11 ...RC5.jl; encrypt; line: 120
				       +1 3  ...RC5.jl; encrypt; line: 122
					  6  ...RC5.jl; test_bits; line: 462
					  7  ...RC5.jl; test_bits; line: 463
				       8   .../RC5.jl; solve; line: 502
				       2   .../RC5.jl; solve; line: 508
					 2 string.jl; println; line: 8
				       +1 2 string.jl; println; line: 5
				       +4 2 string.jl; print; line: 4
				     5   ...Solve.jl; key_from_encrypt; line: 12
				       2 ...Solve.jl; eq; line: 39
					1 array.jl; collect; line: 264
					 1 task.jl; done; line: 82
					  1 task.jl; consume; line: 68
					1 array.jl; collect; line: 265
				       2 ...Solve.jl; eq; line: 40
					 2 array.jl; collect; line: 264
					  2 task.jl; done; line: 82
				       +1 2 task.jl; consume; line: 68
				       1 ...Solve.jl; eq; line: 41
					 1 array.jl; collect; line: 265

Now that's the profile after fixing a few things.  The initial data showed
that:

(1) the fix I had done to encrypt() (adding the mutable output structure) had
no real effect in the larger scheme of things (so I reverted the code, since
it was ugly).

(2) the first slow spot was a call to zip(...).  I replaced that with an
explicit loop over indices.

(3) the second slow spot was an increment of the state being searched over.
This was an integer, so a significant chunk of my program's time was basically
spent adding 1 to a value.  That seemed a bit odd (although it's true it was
the innermost operation).  But it turned out that I was selecting the smallest
integer I needed (typically Uint16) and replacing that with Uint64 for all
cases speeded things up significantly.

So the lessons are:

 - profile before optimising the "obvious" (as ever!)

 - avoid exotic integer types when they are not needed (unfortunately I do
   need them in the core crypto, which relies on overflow).

 - avoid high level functional idioms (like zip) in the inner loop.

The last of these is a disappointment.  I wonder if the optimizer will improve
one day.

Andrew