In this blog post, I will demonstrate how to run and use sysbench histograms.
One of the features of sysbench that I often I see overlooked (and rarely used) is its ability to produce detailed query response time histograms in addition to computing percentile numbers. Looking at histograms together with throughput or latency over time provides many additional insights into query performance.
Here is how you get detailed sysbench histograms and performance over time:
|
1 |
sysbench --rand-type=uniform --report-interval=1 --percentile=99 --time=300 --histogram --mysql-password=sbtest oltp_point_select --table_size=400000000 run |
There are a few command line options to consider:
- report-interval=1 – prints out the current performance measurements every second, which helps see if performance is uniform, if you have stalls or otherwise high variance
- percentile=99 – computes 99 percentile response time, rather than 95 percentile (the default); I like looking at 99 percentile stats as it is a better measure of performance
- histogram=on – produces a histogram at the end of the run (as shown below)
The first thing to note about this histogram is that it is exponential. This means the width of the buckets changes with higher values. It starts with 0.001 ms (one microsecond) and gradually grows. This design is used so that sysbench can deal with workloads with requests that take small fractions of milliseconds, as well as accommodate requests that take many seconds (or minutes).
Next, we learn some us very interesting things about typical request response time distribution for databases. You might think that this distribution would be close to some to some “academic” distributions, such as normal distribution. In reality, we often observe is something of a “camelback” distribution (not a real term) – and our “camel” can have more than two humps (especially for simple requests such as the single primary key lookup shown here).
Why do request response times tend to have this distribution? It is because requests can take multiple paths inside the database. For example, certain requests might get responses from the MySQL Query Cache (which will result in the first hump). A second hump might come from resolving lookups using the InnoDB Adaptive Hash Index. A third hump might come from finding all the data in memory (rather than the Adaptive Hash Index). Finally, another hump might coalesce around the time (or times) it takes to execute on requests that require disk IO.
You also will likely see some long-tail data that highlights the fact that MySQL and Linux are not hard, real-time systems. As an example, this very simple run with a single thread (and thus no contention) has an outlier at around 18ms. Most of the requests are served within 0.2ms or less.
As you add contention, row-level locking, group commit and other issues, you are likely to see even more complicated diagrams – which can often show you something unexpected:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 |
Latency histogram (values are in milliseconds) value ------------- distribution ------------- count 0.050 | 1 0.051 | 2 0.052 | 2 0.053 | 54 0.053 | 79 0.054 | 164 0.055 | 883 0.056 |* 1963 0.057 |* 2691 0.059 |** 4047 0.060 |**** 9480 0.061 |****** 15234 0.062 |******** 20723 0.063 |******** 20708 0.064 |********** 26770 0.065 |************* 35928 0.066 |************* 34520 0.068 |************ 32247 0.069 |************ 31693 0.070 |*************** 41682 0.071 |************** 37862 0.073 |******** 22691 0.074 |****** 15907 0.075 |**** 10509 0.077 |*** 7853 0.078 |**** 9880 0.079 |**** 10853 0.081 |*** 9243 0.082 |*** 9280 0.084 |*** 8947 0.085 |*** 7869 0.087 |*** 8129 0.089 |*** 9073 0.090 |*** 8364 0.092 |*** 6781 0.093 |** 4672 0.095 |* 3356 0.097 |* 2512 0.099 |* 2177 0.100 |* 1784 0.102 |* 1398 0.104 | 1082 0.106 | 810 0.108 | 742 0.110 | 511 0.112 | 422 0.114 | 330 0.116 | 259 0.118 | 203 0.120 | 165 0.122 | 126 0.125 | 108 0.127 | 87 0.129 | 83 0.132 | 55 0.134 | 42 0.136 | 45 0.139 | 41 0.141 | 149 0.144 | 456 0.147 | 848 0.149 |* 2128 0.152 |** 4586 0.155 |*** 7592 0.158 |***** 13685 0.160 |********* 24958 0.163 |***************** 44558 0.166 |***************************** 78332 0.169 |************************************* 98616 0.172 |**************************************** 107664 0.176 |**************************************** 107154 0.179 |**************************** 75272 0.182 |****************** 49645 0.185 |**************** 42793 0.189 |***************** 44649 0.192 |**************** 44329 0.196 |****************** 48460 0.199 |***************** 44769 0.203 |********************** 58578 0.206 |*********************** 61373 0.210 |********************** 58758 0.214 |****************** 48012 0.218 |************* 34533 0.222 |************** 36517 0.226 |************* 34645 0.230 |*********** 28694 0.234 |******* 17560 0.238 |***** 12920 0.243 |**** 10911 0.247 |*** 9208 0.252 |**** 10556 0.256 |*** 7561 0.261 |** 5047 0.266 |* 3757 0.270 |* 3584 0.275 |* 2951 0.280 |* 2078 0.285 |* 2161 0.291 |* 1747 0.296 |* 1954 0.301 |* 2878 0.307 |* 2810 0.312 |* 1967 0.318 |* 1619 0.324 |* 1409 0.330 | 1205 0.336 | 1193 0.342 | 1151 0.348 | 989 0.354 | 985 0.361 | 799 0.367 | 671 0.374 | 566 0.381 | 537 0.388 | 351 0.395 | 276 0.402 | 214 0.409 | 143 0.417 | 80 0.424 | 85 0.432 | 54 0.440 | 41 0.448 | 29 0.456 | 16 0.464 | 15 0.473 | 11 0.481 | 4 0.490 | 9 0.499 | 4 0.508 | 3 0.517 | 4 0.527 | 4 0.536 | 2 0.546 | 4 0.556 | 4 0.566 | 4 0.587 | 1 0.597 | 1 0.608 | 5 0.619 | 3 0.630 | 2 0.654 | 2 0.665 | 5 0.677 | 26 0.690 | 298 0.702 | 924 0.715 |* 1493 0.728 | 1027 0.741 | 1112 0.755 | 1127 0.768 | 796 0.782 | 574 0.797 | 445 0.811 | 415 0.826 | 296 0.841 | 245 0.856 | 202 0.872 | 210 0.888 | 168 0.904 | 217 0.920 | 163 0.937 | 157 0.954 | 204 0.971 | 155 0.989 | 158 1.007 | 137 1.025 | 94 1.044 | 79 1.063 | 52 1.082 | 36 1.102 | 25 1.122 | 25 1.142 | 16 1.163 | 8 1.184 | 5 1.205 | 7 1.227 | 2 1.250 | 4 1.272 | 3 1.295 | 3 1.319 | 2 1.343 | 2 1.367 | 1 1.417 | 2 1.791 | 1 1.996 | 2 2.106 | 2 2.184 | 1 2.264 | 1 2.347 | 2 2.389 | 1 2.433 | 1 2.477 | 1 2.568 | 2 2.615 | 1 2.710 | 1 2.810 | 1 2.861 | 1 3.187 | 1 3.488 | 1 3.816 | 1 4.028 | 1 6.913 | 1 7.565 | 1 8.130 | 1 17.954 | 1 |
I hope you give sysbench histograms a try, and see what you can discover!
Comments (6)
That looks like a feature I should be using. Is there an option to set the number of buckets?
Mark,
Nope. But I already asked Alexey Kopytov to at least allow to specify number of buckets to print out.
High number of buckets is good to compute accurate 99% but we do not need so many for printout
Too many lines of output is one concern. Too much CPU spent searching for the right bucket is the other concern. But I can run tests to determine whether my other concern is bogus.
Mark, I don’t think the number of buckets has any measurable impact on performance (the bucket index is calculated as “i = floor((log(value) – h->range_deduct) * h->range_mult + 0.5)”).
As to making the output more configurable, there is https://github.com/akopytov/sysbench/issues/170 which I’m going to close it together with some other related improvements.
The buckets are logarithmicly spaced, OK. But it closes up the gaps, bad. That distorts the results.
Rick,
Yep. You can surely imagine some cases where the gaps which are skipped would visually misrepresent the picture.