A problem with Timing

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?

-
timeAvg (this flavor being my own construction) merely runs Timing multiple times (by increasing powers of five), until the total exceeds a threshold (here a hard-coded 0.3), then finds the average timing. Therefore the difference you observe on the first Timing would be reduced but not eliminated. I am now exploring why the first Timing is less in this case. – Mr.Wizard Jun 8 '14 at 14:47

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).

-
I'm no expert on timing issues, but Table[With[{t1 = SessionTime[]}, Prepend[M, V]; SessionTime[] - t1], {10}] gives consistent timings, roughly equivalent to the fastest time. – Michael E2 Jun 8 '14 at 15:00
@MichaelE2 Please comment on the observation included at the bottom of my post. – Mr.Wizard Jun 8 '14 at 15:05
@Mr.Wizard - the problem persists with list = {}; Do[AppendTo[list, Prepend[M, V]; // Timing // First], {10}] – eldo Jun 8 '14 at 15:05
@eldo Yes, and also with (Prepend[M, V]; // Timing // First) & /@ Range[10]. More significantly I think the faster timings are in error based on the observation about "wall clock" time. This deserves further exploration but from me at least it will have to wait. – Mr.Wizard Jun 8 '14 at 15:07
Mr.W, I personally associate such differences in timings with garbage collection and other "administrative" tasks of MMA, like the tracking of symbols. Here there are no symbols involved, so I guess that excludes at least the latter possibility. I wish I had more time to investigate. I just wanted to point to this possible angle of the problem, as I also didn't see that in the linked Q&A. – Jacob Akkerboom Jun 8 '14 at 16:40