I'm trying to monitor the execution of a process and sample the number of its retired instructions using perf_event on linux. I want to sample the process at a fixed, constant sampling period over time.
Everything seems to be working for good, I have successfully written the code, which calls perf_event_open() and sets up two different counters:
PERF_TYPE_HARDWARE type, identified as PERF_COUNT_HW_CPU_CYCLES, which works as my 'sampling' event. I specify its sampling period to be 10000.0x00c4) Perf_event correctly samples the target process, allowing me to access its samples via a shared mmap()ed section of memory.
I then write the obtained values inside a file and save them as a matrix, whereas to each n-th column corresponds the n-th sample, and to each row a completely new measurement run.
I report here some random rows from the matrix:
910 1963 3159 4384 5631 6858 8114 9362 10303 15511 21270 26984 32818 38601 44157 49837 55500
768 1924 3161 4404 5651 6890 8133 9370 10274 14987 20740 26539 32350 38133 43692 49360 55085
759 1801 3025 4274 5518 6755 8001 9246 10264 14171 19871 25563 31362 37102 42663 48310 53980
617 1459 2322 3135 3972 4741 5518 6260 7043 7850 8657 9446 10218 11339 14040 16389 18924 21325 23831 26581 29174 31774 34566 37294 39873 42588 45290 47869 50523 53334 55784 57535
855 2006 3248 4483 5729 6951 8198 9440 10334 15637 21401 27168 32979 38799 44341 50065 55756
688 1463 2242 2978 3738 4376 5094 5811 6467 7151 7814 8488 9042 9741 10278 12218 14425 16995 19598 22327 24941 27632 30176 32780 35289 37703 40501 43329 45939 49551 55116
748 1929 3175 4423 5666 6911 8150 9392 10272 14469 20152 25922 31691 37510 43099 48732 54464
775 1950 3190 4429 5674 6914 8157 9397 10275 15093 20848 26675 32437 38241 43764 49512 55129
787 1840 2947 4192 5427 6656 7766 8885 9994 11547 17023 22712 28515 34282 40051 45726 51421 57066
883 2073 3310 4558 5790 7033 8283 9532 10357 15754 21475 27231 33061 38831 44472 50195 55849
798 1996 3239 4461 5706 6950 8199 9441 10275 15229 21009 26783 32626 38414 43977 49707 55429
736 1486 2262 2863 3665 4388 4987 5707 6313 6892 7634 8355 9058 9730 10271 11794 14023 16123 17814 20313 22850 25413 27924 30670 33231 35726 38003 40310 42840 44565 46475 47660 51698 57085
627 1814 3048 4296 5540 6776 8026 9273 10264 13855 19581 25328 31167 36929 42462 48098 53746 57523
920 2062 3310 4547 5794 7029 8267 9517 10496 15891 21649 27425 33213 38931 44435 50107 55746
The problem is that I get rows of different length :(
I obtain a different number of samples for different measurement runs.
The final values is always the same (~55000), but in certain rows I nearly get the double number of samples. The only explanation I've come up with is that the kernel sometimes arbitrarily decides to modify the sampling period.
Is this possible?
How can I be sure the sampling_period to be constant kernel-side while processed to perf_event?
EDIT:
As suggested, I have investigated the dmesg kernel log: I was expecting to find a message about the kernel dynamically modifying the sampling period, as implemented in the kernel function perf_duration_warn() in linux/4.11.3/kernel/events/core.c , but nothing is displayed.
In order to try solving the problem I have decided to modify the perf_event_max_sample_rate and perf_cpu_time_max_percent values before starting my measurements as follows:
sudo sysctl -w kernel/perf_cpu_time_max_percent=0
sudo sysctl -w kernel/perf_event_max_sample_rate=1000000
I have also found out that the time event I'm using to sample can be affected to CPU frequency scaling. In order to avoid that issue, before starting my measurements I constrain all cpus to work on powersave, constant frequency:
for (( i = 0; i < 8; i++ )); do
sudo cpufreq-set -g powersave -c $((i))
done
Even after these precautions, I still get a different number of samples at each measurement, I'll report here some rows:
880 2064 3316 4582 5837 7088 8339 9595 10585 15868 21519 27263 33080 38859 44472 50216 55836
927 2084 3324 4574 5815 7050 8303 9544 10683 16008 21743 27449 33213 38982 44511 50262 55965
749 1825 3063 4306 5575 6818 8070 9317 10262 13926 19637 25396 31207 36995 42539 48096 53800
629 1466 2323 3130 3926 4702 5439 6198 6918 7516 8114 8708 9351 10034 10734 12957 15283 17657 20200 22771 25464 28114 30451 32899 35225 37775 40371 43050 45609 48342 53820
886 2063 3299 4208 5006 5814 6683 7565 8435 9336 10130 11222 13600 17364 23080 28853 34643 40365 45965 51625 57237
821 2001 3251 4495 5733 6986 8247 9480 10265 12197 14699 17284 19897 22463 25141 28072 30695 33320 35964 38750 44183 49872 55515
917 2071 3320 4562 5801 7029 8275 9508 10509 15865 21575 27317 33118 38916 44566 50256 55923
472 1573 2806 4044 5270 6514 7743 8977 10217 13221 18923 24610 30389 36127 41717 47398 53076 57518
924 1980 3225 4477 5712 6946 8183 9435 10353 15575 21318 27078 30246 32751 35310 37808 40322 42769 45306 47800 50340 52852 55395 57499
932 2038 3270 4527 5655 6907 8030 9139 10237 13390 18965 24708 30389 36115 41719 47397 53030 57520
927 2088 3327 4581 5826 7078 8316 9549 10692 16007 21726 27449 33235 39001 44564 50225 55890
582 1405 2263 3061 3859 4651 5370 6170 6861 7461 8017 8601 9153 9808 10281 12318 14509 16810 19173 21820 24183 26912 29796 32447 34809 37347 39652 42216 44943 47728 50588 53182 57081
903 2065 3320 4546 5795 7025 8272 9515 10294 15324 21081 26863 32644 38439 43975 49714 55388
921 2094 3325 4571 5810 7045 8296 9548 10759 16134 21869 27560 33412 39154 44837 50581 56307
860 2049 3284 4525 5771 7025 8283 9532 10415 15646 21325 27056 32827 38560 44065 49691 55352
953 2124 3368 4610 5844 7071 8317 9575 10790 16141 21889 27642 33406 39151 44725 50435 56092
921 2098 3338 4529 5311 6160 7030 7910 8792 9644 10293 12630 14972 17493 20388 26173 31915 37689 43267 48951 54696
575 1384 2040 2841 3511 4068 4680 5386 6086 6677 7244 7828 8476 9104 9761 10279 11976 14187 16747 19192 21859 24662 26853 29386 31702 34421 36952 39444 41934 44699 47371 49965 52794 57509
925 2101 3333 4575 5814 7066 8318 9562 10849 16188 21910 27648 33348 39069 44626 50245 55877
591 1462 2321 3140 3975 4731 5494 6279 7042 7684 8252 8831 9415 10066 10793 13202 15480 17800 20151 22779 25268 27824 30673 33340 35680 38182 40851 43263 45995 48661 51409 54078 56696
885 1927 3041 4157 5024 5779 6615 7473 8289 9124 9883 10440 12771 17987 23720 29495 35303 40764 46468 52157 57485
Do someone has any idea of where I can possibly further investigate this problem?
EDIT 3
I have increased the sampling period from 10000 to 100000 to see what does it happen: I get lesser 'longer' rows, but the problem still persists and I get rows of different length unfortunately
I have solved the issue.
In order to be sure to be effectively sampling at a constant period of time using the perf_event system call, it is required to:
sample_period field inside the perf_event_attr struct. As documented in perf wiki tutorial you should pay attention on that number exceeding a value representable as 32 bits, otherwise the system will silently truncates it.sample_freq field inside the perf_event_attr struct. If you do so, the kernel will dynamically change the sampling period in order to achieve the desired frequency, as documented in perf wiki tutorialdmesg the kernel log: you should not get any kind of message. Otherwise, as suggested by Arnabjyoti Kalita, the sampling period value may be too near to the maximum set in the kernel variable perf_event_max_sample_rate. In that case the best approach is to modify the kernel variable using sudo sysctl -w kernel/perf_cpu_time_max_percent=0, such that the kernel won't by default modify the sampling period even if this may bring the computer to get stuck.
The kernel implements this functionality to avoid becoming stuck when too many PMI (Performance Monitoring Interrupts) take too much computation time. Those interrupt are hooked by the perf_event functionality and will be triggered when the sampling event overflows out of the specified sampling period value.
For further information about the perf_event kernel variables, consult the documentation you can find in the kernel source code at linux-VERSION/Documentation/sysctl/kernel.txtsudo cpufreq-set -g powersave -c $((i)) such that your cpu's measurements won't be affected
by frequency scaling.I asked this question because I believed that getting a different number of samples is related to the kernel modifying the sampling period.
It is not. (It may be but not in my case)
The reason I get a different number of samples is because any kind of monitored thread may take, during its execution, a different time to execute. To those 'longer' lines indeed I obtain a bigger time value. This is due to the fact that the process may have occasionally some cache misses or different mispredicted branches.
Some futher work to be done in this direction may be:
If someone finds out new informations about this, please comment/modify the answer or contact me.