A problem with Timing

Question

With

M = Partition[Range@10000000, 1000];  
V = Range[10000] - 1;

I got the following timings:

Table[Prepend[M, V]; // Timing // First, {10}]

{0.358802, 0.561603, 0.546003, 0.546003, 0.577203, 0.592803, \ 0.561603, 0.577203, 0.561603, 0.561603}

I was irritated by the fact that the first timing (0.358802) was significantly faster than the others. This also happened with similar functions and other sizes of M and V. Later I found the timing function recommended here:

timeAvg = 
  Function[func, 
   Do[If[# > 0.3, Return[#/5^i]] & @@ Timing@Do[func, {5^i}], {i, 0, 
     15}], HoldFirst];

Using it I now get a much "better" result:

Table[Prepend[M, V]; // timeAvg, {10}]

{0.574083, 0.514803, 0.577203, 0.561603, 0.546003, 0.546003, \ 0.561603, 0.546003, 0.546003, 0.530403}

Why the initial jump with the inbuilt Timing?
Should I always use timeAvg?

Answer 1

I am reversing the order of this answer, putting new observations first, as I think that is most helpful.

I suddenly realized that you are "prepending" a vector V that does not match the row dimension of the packed array M. This means that unpacking will occur, and it seems to be full unpacking. If instead we append a vector of length 1000 we will not unpack, and the timings look very different:

M = Partition[Range@10000000, 1000];
V = Range[1000] - 1;

Table[Prepend[M, V]; // Timing // First, {10}]

{0.016, 0., 0., 0., 0.015, 0.016, 0.015, 0., 0.016, 0.016}

(The small values e.g. 0.016 are from the limited clock precision on my machine.)
The point is that the time is being spent on unpacking rather than appending the vector.
We can also manually unpack only the top level using List @@:

M = List @@ Partition[Range@10000000, 1000];
V = Range[10000] - 1;
Table[Prepend[M, V]; // Timing // First, {10}]

{0., 0., 0., 0., 0., 0., 0., 0., 0., 0.}

---

I think the first Timing on each line is inaccurate, or at least is measuring something else. This sounds familiar to me actually, but I can't quite recall now. Nevertheless if I enter e.g. ten lines of:

Prepend[M, V]; // AbsoluteTiming // First

Most timings are about 0.1 second, yet the total "wall clock" time is about two seconds, not one.

---

I am still seeking the underlying cause of this timing discrepancy, which I am able to reproduce in version 7, but for now I observe that it does not happen outside of Table:

M = Partition[Range@10000000, 1000];
V = Range[10000] - 1;

Prepend[M, V]; // Timing // First
Prepend[M, V]; // Timing // First
Prepend[M, V]; // Timing // First
Prepend[M, V]; // Timing // First

0.109
0.109
0.11
0.109

On the other hand using AbsoluteTiming yields a first result that is slower:

M = Partition[Range@10000000, 1000];
V = Range[10000] - 1;

Prepend[M, V]; // AbsoluteTiming // First
Prepend[M, V]; // AbsoluteTiming // First
Prepend[M, V]; // AbsoluteTiming // First
Prepend[M, V]; // AbsoluteTiming // First

0.1560089
0.1090063
0.1050060
0.1060061

I think this might be explained by the system being "primed" by the first operation, with operands maximally cached, etc. When using AbsoluteTiming in Table the first result is about the same, but all the rest are about twice as large (slow).