perf-tools
perf-tools copied to clipboard
brendangregg
cachestat shows negative numbers
Hi, i dont think this is normal:
# sh cachestat -D 5
Counting cache functions... Output every 5 seconds.
HITS MISSES DIRTIES RATIO BUFFERS_MB CACHE_MB DEBUG
-3075 0 5748 100.0% 299 119830 (2673 5748 2023 5741)
-3798 0 7365 100.0% 299 119841 (3567 7365 3069 7383)
-2333 0 5245 100.0% 299 119850 (2912 5245 1929 5240)
-2469 0 4877 100.0% 299 119858 (2408 4877 2068 4832)
-1782 0 4761 100.0% 299 119867 (2979 4761 2506 4742)
-1981 0 4393 100.0% 299 119876 (2412 4393 2194 4379)
2811 0 3719 100.0% 299 119883 (6530 3719 1832 3709)
7 0 2145 100.0% 299 119886 (2152 2145 873 2140)
53008 0 10504 100.0% 299 119902 (63512 10504 4412 10420)
-5710 0 15480 100.0% 299 119902 (9770 15480 7456 15471)
This is on RHEL.
does it wrap around or something ?
Hi there, I'm also getting negative numbers from cachestat
Counting cache functions... Output every 60 seconds.
TIME HITS MISSES DIRTIES RATIO BUFFERS_MB CACHE_MB
13:48:25 47378 250428 69552 15.9% 0 12722
13:49:25 43849 193952 101414 18.4% 0 12577
13:50:25 222238 193775 68748 53.4% 0 12274
13:51:25 52056 304176 76151 14.6% 0 12346
13:52:25 -91561 453830 69980 -25.3% 0 11994
13:53:25 -201668 489211 83497 -70.1% 0 11352
13:54:25 193888 435421 351975 30.8% 0 10817
13:55:25 180081 349623 46108 34.0% 0 11820
13:56:25 31362 186683 78163 14.4% 0 12237
13:57:25 24289 238327 41534 9.2% 0 12281
13:58:25 31988 292461 82240 9.9% 0 12234
13:59:25 -9833 464097 78400 -2.2% 0 11965
What's the meaning of this negative number?
Cheers, Justin
I'm seeing this too, it looks like mark_page_accessed is always less than add_to_page_cache_lru on my system.
here's a debug sample output:
-14940 17161 16840 -672.7% 1 122444 (19061 16840 27307 10146)
-11838 13827 7424 -595.2% 1 122405 (9413 7424 18136 4309)
-13269 16852 3381 -370.3% 1 122408 (6964 3381 19098 2246)
-11092 11730 5232 -1738.6% 1 122443 (5870 5232 14617 2887)
-14577 18153 2381 -407.6% 1 122450 (5957 2381 19808 1655)
-20268 24610 2600 -466.8% 1 122424 (6942 2600 26363 1753)
-16625 17292 624 -2492.5% 1 122431 (1291 624 17475 183)
-32225 35704 1716 -926.3% 1 122447 (5195 1716 36924 1220)
-22242 22865 343 -3570.1% 1 122443 (966 343 22880 15)
-23125 26668 1612 -652.7% 1 122462 (5155 1612 28079 1411)
-22768 26362 1707 -633.5% 1 122402 (5301 1707 27581 1219)
-19224 19878 398 -2939.4% 1 122402 (1052 398 19898 20)
-16710 20149 1631 -485.9% 1 122403 (5070 1631 21368 1219)
-13992 14639 388 -2162.6% 1 122435 (1035 388 14658 19)
-5883 9331 1636 -170.6% 1 122463 (5084 1636 10538 1207)
-12594 16562 2139 -317.4% 1 122434 (6107 2139 18034 1472)
2865 11643 736 19.7% 1 122403 (15244 736 11884 241)
-4603 8191 4313 -128.3% 1 122434 (7901 4313 10968 2777)
-12941 13621 1767 -1903.1% 1 122404 (2447 1767 14432 811)
-19163 22724 4402 -538.1% 1 122455 (7963 4402 25630 2906)
-11509 15052 1798 -324.8% 1 122460 (5341 1798 16415 1363)
-25100 25641 9879 -4639.6% 1 122428 (10420 9879 31278 5637)
-8871 12482 13205 -245.7% 1 122400 (16816 13205 20354 7872)
-8066 10161 3567 -385.0% 1 122431 (5662 3567 12541 2380)
-11778 14137 3055 -499.3% 1 122421 (5414 3055 15755 1618)
-6892 10464 7094 -192.9% 1 122435 (10666 7094 15013 4549)
-8650 9293 5954 -1345.3% 1 122409 (6597 5954 12460 3167)
-13613 17195 8731 -380.0% 1 122450 (12313 8731 22247 5052)
-7297 9503 18290 -330.8% 1 122418 (20496 18290 19236 9733)
-11023 13046 20264 -544.9% 1 122403 (22287 20264 23945 10899)
-6365 9853 44378 -182.5% 1 122440 (47866 44378 37108 27255)
-8329 8963 2155 -1313.7% 1 122422 (2789 2155 10054 1091)
-2718 6149 2551 -79.2% 1 122448 (5982 2551 7895 1746)
-4972 8512 1600 -140.5% 1 122388 (5140 1600 9863 1351)
-10393 11405 376 -1027.0% 1 122432 (1388 376 11423 18)
117 10656 2641 1.1% 1 122399 (13414 2641 12512 1856)
-4294 14385 5106 -42.6% 1 122432 (15197 5106 17204 2819)
-10064 13603 1923 -284.4% 1 122421 (5462 1923 15024 1421)
-5549 9118 4454 -155.5% 1 122395 (8023 4454 12098 2980)
-11976 12631 1335 -1828.4% 1 122440 (1990 1335 13221 590)
-3173 3666 106 -643.6% 1 122402 (599 106 3670 4)
root@sjc1-b6-4:/tmp# uname -a
Linux sjc1-b6-4 3.13.0-85-generic #129-Ubuntu SMP Thu Mar 17 20:50:15 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
Is it possible mark_page_accessed is no longer called every time add_to_page_cache_lru is?
I am also facing the same problem. May I know the reason and how to resolve it? @brendangregg Thanks.
Hmmm. I'm on Debian and do not see this problem.
rrs@priyasi:~$ sudo cachestat-perf
[sudo] password for rrs:
Counting cache functions... Output every 1 seconds.
HITS MISSES DIRTIES RATIO BUFFERS_MB CACHE_MB
1769 2 0 99.9% 91 2423
1743 0 0 100.0% 91 2423
1928 0 0 100.0% 91 2423
1837 0 61 100.0% 91 2423
1805 0 0 100.0% 91 2423
1804 0 0 100.0% 91 2422
1786 0 0 100.0% 91 2422
1778 0 0 100.0% 91 2423
1915 0 2 100.0% 91 2421
1790 0 2 100.0% 91 2421
1743 0 0 100.0% 91 2421
1764 0 84 100.0% 91 2421
1776 0 0 100.0% 91 2421
1805 0 0 100.0% 91 2421
^C 1778 0 0 100.0% 91 2421
Ending tracing...
15:50 ♒♒♒ ☺
rrs@priyasi:~$ uname -a
Linux priyasi 4.12.4+ #42 SMP Mon Jul 31 22:45:58 IST 2017 x86_64 GNU/Linux
15:51 ♒♒♒ ☺
Nope. I'll take my statement back. After running for some time, I could see the negative numbers.
rrs@priyasi:~$ sudo cachestat-perf -D 3
Counting cache functions... Output every 3 seconds.
HITS MISSES DIRTIES RATIO BUFFERS_MB CACHE_MB DEBUG
826 15274 356 5.1% 44 2727 (16456 356 15563 289)
-12106 25394 488 -91.1% 44 2810 (13776 488 25732 338)
-4699 18167 406 -34.9% 45 2886 (13874 406 18492 325)
16073 15121 723 51.5% 45 2840 (31917 723 15524 403)
31290 3155 300 90.8% 45 2857 (34745 300 3308 153)
2124 227 370 90.3% 45 2859 (2721 370 483 256)
1975 11 38 99.4% 45 2859 (2024 38 20 9)
1932 0 16 100.0% 45 2856 (1948 16 5 6)
889 1671 154 34.7% 45 2861 (2714 154 1764 93)
7265 72 2 99.0% 45 2864 (7339 2 72 0)
1965 258 27 88.4% 45 2868 (2250 27 266 8)
3505 10 0 99.7% 45 2881 (3515 0 10 0)
2592 1214 4 68.1% 45 2879 (3810 4 1214 0)
27131 627 91 97.7% 45 2863 (27849 91 639 12)
5142 38 166 99.3% 45 2864 (5346 166 149 111)
5857 2 31 100.0% 45 2853 (5890 31 12 10)
2809 0 98 100.0% 45 2859 (2907 98 69 69)
1565 576 141 73.1% 45 2856 (2282 141 674 98)
6090 7108 222 46.1% 47 2876 (13420 222 7280 172)
5526 503 111 91.7% 47 2884 (6140 111 556 53)
8618 20 16 99.8% 47 2880 (8654 16 27 7)
1985 0 138 100.0% 47 2876 (2123 138 56 102)
1065 2655 2 28.6% 47 2884 (3722 2 2655 0)
1838 2 58 99.9% 47 2884 (1898 58 41 39)
1757 2 29 99.9% 47 2884 (1788 29 6 4)
1804 0 25 100.0% 47 2884 (1829 25 8 8)
10735 456 13 95.9% 47 2886 (11204 13 469 13)
^C 19291 272 18 98.6% 47 2887 (19581 18 289 17)
Ending tracing...
15:58 ♒♒♒ ☺
I have no clue. The tool does mention that it may misbehave with newer kernels, and was written initially for the 3.13 kernel only.
From the man page I wrote:
Its current implementation uses Linux ftrace dynamic function profiling
to create custom in‐kernel counters, which is a workaround until such
counters can be built‐in to the kernel. Specifically, four kernel func‐
tions are counted:
mark_page_accessed() for measuring cache accesses
mark_buffer_dirty() for measuring cache writes
add_to_page_cache_lru() for measuring page additions
account_page_dirtied() for measuring page dirties
It is possible that these functions have been renamed (or are different
logically) for your kernel version, and this script will not work as‐
is. This was written for a Linux 3.13 kernel, and tested on a few oth‐
ers versions. This script is a sandcastle: the kernel may wash some
away, and you’ll need to rebuild.
This program’s implementation can be improved in the future when other
kernel capabilities are made available. If you need a more reliable
tool now, then consider other tracing alternatives (eg, SystemTap).
This tool is really a proof of concept to see what ftrace can currently
do.
WARNING: This uses dynamic tracing of kernel functions, and could cause
kernel panics or freezes. Test, and know what you are doing, before
use. It also traces cache activity, which can be frequent, and cost
some overhead. The statistics should be treated as best‐effort: there
may be some error margin depending on unusual workload types.
Please read the man pages.
I also wrote a blog post on this tool in particular, http://www.brendangregg.com/blog/2014-12-31/linux-page-cache-hit-ratio.html with the conclusion:
Hopefully in the future the kernel will provide an easy way to measure page cache activity, be it from /proc or tracepoints. In the meantime, I have cachestat which works for my kernel versions. Its current implementation is brittle, and may not work well on other versions without modifications, so its greatest value may be showing what can be done with a little effort.
I've tried to make it abundantly clear that this tool is brittle, and will need hand-holding to work on any given kernel, until either tracepoints exist or /proc statistics. I'll do the temporary hand-holding for the kernels my employer uses, but I'm too busy to do that for every kernel that exists. If this sounds like cachestat is too brittle and there should be a better way, then yes, that's what I've been saying all along. I may well contribute to fixing the kernel with one of those better ways, when it gets to the top of my todo list. Fell free to help with that kernel work, which might include fixing Keiichi's page monitoring patch to work on newer kernels, and then getting it merged. Once we have tracepoints (or /proc), cachestat will need one update and will then work forever.
Since writing this ftrace version, it's been ported to bcc, and the probes were posted to the linux-mm mailing list to see if those engineers (who actually wrote the kernel memory allocation code) agreed with the methodology. Last I heard there was no response. So right now, no one has told me there's a better way than what I'm already doing. And what I'm doing is pretty brittle. We need to improve the kernel.
