Statistical methods for latency profiling

Hey,

Recently Ingo Molnar asked in one of the voluntary-preempt threads for the minimum and average scheduling delay reported by jackd. JACK does not currently maintain these statistics.

I realized that the distribution of maximum latencies reported on each process cycle is fairly normally distributed. If this data followed a normal distribution, it becomes much easier to make generalizations about it - the standard deviation becomes meaningful, we can identify whether a change is statistically significant, etc. It would also indicate the effectiveness of the Linux scheduler by identifying any skew - the distribution in fact should be normal, as the only factor that should be influencing this value is the variance in lengths of whatever non-preemptible sections the kernel was in when we became runnable.

The first step in being able to meaningfully analyze these results is to determine the degree to which distribution is in fact normal. The first step in this process is to just to look at a histogram of the data.

In any jackd engine, the allowable window for scheduler latency is:

	(0,  period_usecs/2)

A latency in the range:

[period_usecs/2, period_usecs]

will cause jackd to restart, and of course anything over period_usecs is an XRUN.

Thus we can build a histogram of the observed latencies by creating an array with period_usecs/2 elements, and adding 1 to each "bin" whenever we see that value. Using 32 frames at 48KHz, we have 333 "bins".

The overhead is not too bad, because we only look at the highest latency for each period (max_usecs), so we only have to update the histogram once per period - if the underlying distribution is normal then the distribution of the maximimums will be as well.

The ability to use statistical methods to generalize about this data will be increasingly important moving forward, because this is the *only* way we can provide hard numbers: confidence intervals, p-values, standard deviations, etc. rather than "It feels faster" or "Since $FOO change the system is sluggish". Statistical methods would allow us to say "$FOO change increases the mean latency from 150 to 200 usecs, but the standard deviation is now 20 rather than 75, so it's actually an improvement".

Any change in the kernel that makes a difference in the "feel" of the system is now open to analysis. Many developers apparently do not consider a user report of "It feels sluggish" to be as much of a concern as "X took Y amount of time now it takes Z". Statistical methods can close this gap.

Anyone care to comment?

Lee

PS I did not do very well in my statistics classes, and it's possible that many kernel hackers are completely unfamiliar with statistical methods. Fortunately the subset that is immediately useful to us is pretty easy to understand, and could be covered in one or two lectures, or a HOWTO. Depending on the level of interest I can create one.

This is not at all what I would expect. Instead, I'd expect to see something like a gamma distribution, where we have everything clustered down close to zero, but with a very long tail in the positive direction falling off exponentially and obviously a hard limit on the other side..

Mathematics is the supreme nostalgia of our time.

Right, it is a lot closer to a gamma distribution. It's been years since I have used any of this, and I took stat for psych majors, vs stat for engineers. I was a lot more interested in playing Doom at the time...

This looks interesting:

http://www.itl.nist.gov/div898/handbook/eda/section3/ppccplot.htm
http://www.itl.nist.gov/div898/handbook/eda/section4/eda4291.htm

I will have some numbers soon.

Lee

Here is the histogram from running 500000 cycles (~5 minutes), with max_sectors_kb -> 64, normal desktop usage. Kernel is 2.6.8-rc2-M5, set to 1:3, with all irqs threaded except the sound card.

Delay   Count
-----   -----
6       2257
7       3210
8       797
9       717
10      283
11      219
12      235
13      250
14      263
15      320
16      334
17      287
18      268
19      260
20      223
21      155
22      109
23      90
24      41
25      19
26      3
27      4
28      1
29      3
30      1
31      2
32      5
33      3
34      1
35      7
36      1
37      3
38      4
39      1
40      5
41      8
42      2
43      1
44      1
47      1
48      1
52      2
62      1
79      1
100     1

The next three tests were done with iozone -a running.

Delay   Count
-----   -----
6       21
7       203
8       595
9       1756
10      1643
11      957
12      618
13      507
14      532
15      540
16      523
17      423
18      400
19      424
20      418
21      293
22      202
23      119
24      71
25      38
26      20
27      8
28      7
29      2
30      1
31      1
32      4
33      4
34      7
35      6
36      1
37      2
38      5
39      7
40      3
41      4
42      4
43      1
44      2
47      1
48      1
50      1
53      1
54      1
57      1
59      1
63      1
69      1
70      2
79      1
91      1
92      1
93      1
100     1
101     1
107     1
109     1
113     1
118     1
123     1
131     1
143     1
145     1
146     1
157     1
161     1

So stressing the filesystem moves the center to the right a bit, from 6-7 to 9-10, and *drastically* lengthens the 'tail'.

These numbers suggest to me that a lot of the latencies from 47 usecs and up are caused by one code path, because they are so uniformly distributed over the upper part of the histogram. The prime suspect of course being the ide io completions. I tested this theory by lowering max_sectors_kb from 64 to 32:

Delay   Count
-----   -----
6       3
7       427
8       742
9       1583
10      3429
11      2010
12      614
13      203
14      200
15      275
16      267
17      177
18      104
19      50
20      55
21      36
22      22
23      21
24      22
25      29
26      26
27      9
28      2
29      3
30      1
32      2
33      2
34      2
35      1
36      1
37      2
41      1
42      1
43      1
48      1
65      1
70      1
71      4
72      3
73      6
74      3
75      1
76      1
77      3
78      2
79      4
80      2
81      3
82      3
83      3
84      3
85      2
86      2
87      4
88      4
90      1
91      1
92      3
94      3
96      2
101     2
102     3
103     1
106     1
111     1
112     1
122     1
132     1

Finally, 16:

Delay   Count
-----   -----
6       420
7       1463
8       652
9       1444
10      2365
11      1111
12      537
13      265
14      232
15      241
16      253
17      218
18      173
19      181
20      233
21      188
22      125
23      76
24      55
25      23
26      9
27      15
28      6
29      2
30      2
31      6
32      5
33      9
34      8
35      4
36      2
37      5
38      2
39      1
40      2
41      3
42      3
43      2
45      1
47      1
49      1
51      3
52      1
53      1
54      1
55      1
56      1
57      1
59      2
60      2
61      2
62      2
63      1
64      1
66      2
67      2
68      3
69      1
71      1
72      3
74      2
75      1
76      2
77      1
78      2
79      1
80      1
81      2
82      1
84      1
85      3
86      1
87      1
89      1
90      2
92      1
100     1
101     1

These numbers all point to the ide sg completion code as the only thing on the system generating latencies over ~42 usecs.

I have sent the patch separately to jackit-devel so as not to clutter LKML with unrelated patches.

Lee

basically each codepath has a typical latency distribution, and when a workload uses multiple codepaths then the latencies get intermixed almost linearly.

yep, that's a fair assumption. Once the IO-APIC irq-redirection problems are solved i'll try to further thread the IDE completion IRQ to remove that ~100 usecs latency.

Ingo

I noticed several distinct spikes with 1M samples, that blend into smooth Erlang/gamma type distribution at 5M. I posted some more results to jackit-dev. It seems like each of these would represent a common code path out of a non-preemptible region. I suspect the spike at 70-80 usecs is a bug in my code, from updating the histogram every 1024 cycles. I will start posting results on the web soon, it's getting big.

It would be interesting to identify the code paths corresponding to the other peaks. It occurred to me that if you suspect a peak in the histogram is related to a certain code path, you could stick a udelay in there, and see if the spike moves up by the same amount.

Lee