Skip to content
This repository has been archived by the owner on May 14, 2020. It is now read-only.

Reduce background CPU load? #8

Open
candlerb opened this issue Jan 22, 2020 · 2 comments
Open

Reduce background CPU load? #8

candlerb opened this issue Jan 22, 2020 · 2 comments

Comments

@candlerb
Copy link

I installed microk8s and local-zfs-provisioner on a small low-power cluster (2 x NUC DN2820: processor is Celeron N2820, 2 cores @ 2.13GHz). These boxes are very lightly loaded with lxd containers which are mostly idle. microk8s runs directly on the metal.

I was surprised to see top showing local-zfs-provisioner as consistently the top consumer of CPU, using a continuous 10-15%:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
28251 root      20   0  133448  28316  18812 S  15.1  0.4 171:40.75 local-zfs-provi
21261 root      20   0  496400 332236  55272 S   6.2  4.1 187:06.28 kube-apiserver

and I'm hard pushed to explain why.

strace shows multiple threads with wakeups every 20 microseconds (tv_nsec=20000):

root@nuc1:~# strace -tt -f -p 28251
strace: Process 28251 attached with 11 threads
[pid  3120] 10:25:44.417522 futex(0xc0003b04c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29501] 10:25:44.417909 restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
[pid 28513] 10:25:44.418016 restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
[pid 29501] 10:25:44.418121 <... restart_syscall resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 29501] 10:25:44.418257 futex(0x219eb40, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=983143} <unfinished ...>
[pid 28492] 10:25:44.418433 epoll_pwait(4,  <unfinished ...>
[pid 28489] 10:25:44.419141 futex(0x21b7878, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28488] 10:25:44.419287 futex(0xc00012f2c8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28466] 10:25:44.419501 futex(0xc000110148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29501] 10:25:44.419672 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 28513] 10:25:44.419767 <... restart_syscall resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 29501] 10:25:44.419917 futex(0x219eb40, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=2269632} <unfinished ...>
[pid 28513] 10:25:44.420046 futex(0x219eac0, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=260528} <unfinished ...>
[pid 28423] 10:25:44.420215 futex(0xc000060848, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28420] 10:25:44.420439 futex(0x21b79a0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28419] 10:25:44.420520 restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
[pid 28513] 10:25:44.420653 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 28419] 10:25:44.420775 <... restart_syscall resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
[pid 28513] 10:25:44.420893 futex(0x219eac0, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=320807} <unfinished ...>
[pid 28419] 10:25:44.421044 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 28251] 10:25:44.421309 futex(0x219aea8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28513] 10:25:44.421520 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 28419] 10:25:44.421638 <... nanosleep resumed> NULL) = 0
[pid 28513] 10:25:44.421713 futex(0x219eac0, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=800147} <unfinished ...>
[pid 28419] 10:25:44.421867 futex(0x219a3f0, FUTEX_WAIT_PRIVATE, 0, {tv_sec=60, tv_nsec=0} <unfinished ...>
[pid 29501] 10:25:44.422405 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 29501] 10:25:44.422513 futex(0x219a3f0, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 28419] 10:25:44.422683 <... futex resumed> ) = 0
[pid 29501] 10:25:44.423222 futex(0x219eb40, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=2310843} <unfinished ...>
[pid 28513] 10:25:44.423478 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 28419] 10:25:44.423659 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 28513] 10:25:44.423787 futex(0x219eac0, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=397496} <unfinished ...>
[pid 28419] 10:25:44.424004 <... nanosleep resumed> NULL) = 0
[pid 28419] 10:25:44.424135 futex(0x219a3f0, FUTEX_WAIT_PRIVATE, 0, {tv_sec=60, tv_nsec=0} <unfinished ...>
[pid 28513] 10:25:44.424512 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 28513] 10:25:44.424658 futex(0x219a3f0, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 28419] 10:25:44.424860 <... futex resumed> ) = 0
[pid 28513] 10:25:44.424938 futex(0x219eac0, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=683666} <unfinished ...>
[pid 28419] 10:25:44.425029 nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 28419] 10:25:44.425219 futex(0x219a3f0, FUTEX_WAIT_PRIVATE, 0, {tv_sec=60, tv_nsec=0} <unfinished ...>
[pid 28513] 10:25:44.425773 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 28513] 10:25:44.425845 futex(0x219a3f0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 29501] 10:25:44.425894 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 28513] 10:25:44.425937 <... futex resumed> ) = 1
[pid 29501] 10:25:44.425976 sched_yield( <unfinished ...>
[pid 28513] 10:25:44.426028 futex(0x219eac0, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=196867} <unfinished ...>
[pid 29501] 10:25:44.426116 <... sched_yield resumed> ) = 0
[pid 28419] 10:25:44.426151 <... futex resumed> ) = 0
[pid 29501] 10:25:44.426185 futex(0x219a2f0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 28419] 10:25:44.426250 nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 29501] 10:25:44.426349 <... futex resumed> ) = 0
[pid 28513] 10:25:44.426405 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
...

If I filter out all that background, all that's left is a small amount of communication every couple of seconds (possibly to API?):

root@nuc1:~# strace -t -f -p 28251 2>&1 | egrep -v '(futex|nanosleep|sched_yield)'
strace: Process 28251 attached with 11 threads
[pid 28513] 10:26:47 epoll_pwait(4,  <unfinished ...>
[pid 28466] 10:26:47 <... restart_syscall resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 28423] 10:26:48 write(3, "\27\3\3\0!~\345Ce5\17\302\3460\354\362DX\266)\313R\202\231{\236\266/\332\261\4\202"..., 38 <unfinished ...>
[pid 28423] 10:26:48 <... write resumed> ) = 38
[pid 28513] 10:26:48 <... epoll_pwait resumed> [{EPOLLIN|EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, -1, NULL, 824634889500) = 1
[pid 28513] 10:26:48 read(3, "\27\3\3\0004^\320\272\235\377\216\245\312'\347X\200\34l\374\212\327G\274\365p\221\"\2\332Tq"..., 6861) = 640
[pid  3120] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid  3120] 10:26:48 <... epoll_pwait resumed> [{EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, 0, NULL, 0) = 1
[pid 28513] 10:26:48 read(3,  <unfinished ...>
[pid  3120] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid 28513] 10:26:48 <... read resumed> 0xc0001c4000, 6861) = -1 EAGAIN (Resource temporarily unavailable)
[pid  3120] 10:26:48 <... epoll_pwait resumed> [], 128, 0, NULL, 1) = 0
[pid  3120] 10:26:48 write(3, "\27\3\3\0#a\376\36`\262J\0(\n\177vz\237\251d2Q\312\247\177)\207\364c\335\353R"..., 40 <unfinished ...>
[pid  3120] 10:26:48 <... write resumed> ) = 40
[pid  3120] 10:26:48 write(3, "\27\3\3\2B\307\22)\247\206F\341\312\257#pk\334\243&\4;\32\251ox\210\204\347\207@I"..., 583 <unfinished ...>
[pid  3120] 10:26:48 <... write resumed> ) = 583
[pid  3120] 10:26:48 write(3, "\27\3\3\0\31v.\346\205\tY\200\336b\244\340\363y\4<\343\202\30w\303\10r\r\274\225", 30 <unfinished ...>
[pid  3120] 10:26:48 <... write resumed> ) = 30
[pid 28492] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid  3120] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid 28492] 10:26:48 <... epoll_pwait resumed> [], 128, 0, NULL, 0) = 0
[pid  3120] 10:26:48 <... epoll_pwait resumed> [], 128, 0, NULL, 824642219956) = 0
[pid 28492] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid 28492] 10:26:48 <... epoll_pwait resumed> [{EPOLLIN|EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, -1, NULL, 3) = 1
[pid 28492] 10:26:48 read(3,  <unfinished ...>
[pid 28492] 10:26:48 <... read resumed> "\27\3\3\0\35\27\364g\266y\313\275\\\264+\tz\32bc\251\24f\2005#\200\331)\31{\203"..., 6861) = 68
[pid 28492] 10:26:48 read(3,  <unfinished ...>
[pid  3120] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid 28492] 10:26:48 <... read resumed> 0xc0001c4000, 6861) = -1 EAGAIN (Resource temporarily unavailable)
[pid  3120] 10:26:48 <... epoll_pwait resumed> [{EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, 0, NULL, 0) = 1
[pid  3120] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid 28492] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid 28492] 10:26:48 <... epoll_pwait resumed> [], 128, 0, NULL, 0) = 0
[pid  3120] 10:26:48 <... epoll_pwait resumed> [{EPOLLIN|EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, -1, NULL, 3) = 1
[pid 28492] 10:26:48 read(3,  <unfinished ...>
[pid 28492] 10:26:48 <... read resumed> "\27\3\3\0\35\vA\342k6*I\315'\260\311%q\265\335<\4P[D\230r\321\7\335\315\331"..., 6861) = 617
[pid  3120] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid 28492] 10:26:48 read(3,  <unfinished ...>
[pid  3120] 10:26:48 <... epoll_pwait resumed> [{EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, 0, NULL, 0) = 1
[pid 28492] 10:26:48 <... read resumed> 0xc0001c4000, 6861) = -1 EAGAIN (Resource temporarily unavailable)
[pid  3120] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid  3120] 10:26:48 <... epoll_pwait resumed> [], 128, 0, NULL, 1) = 0
[pid  3120] 10:26:48 epoll_pwait(4,  <unfinished ...>
[pid 28492] 10:26:49 write(2, "time=\"2020-01-22T10:26:49Z\" leve"..., 58 <unfinished ...>
[pid 28492] 10:26:49 <... write resumed> ) = 58
[pid 28492] 10:26:49 openat(AT_FDCWD, "/etc/config/config.json", O_RDONLY|O_CLOEXEC <unfinished ...>
[pid 28492] 10:26:49 <... openat resumed> ) = 6
[pid 28492] 10:26:49 epoll_ctl(4, EPOLL_CTL_ADD, 6, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=1521856056, u64=140713240407608}} <unfinished ...>
[pid 28492] 10:26:49 <... epoll_ctl resumed> ) = -1 EPERM (Operation not permitted)
[pid 28492] 10:26:49 epoll_ctl(4, EPOLL_CTL_DEL, 6, 0xc00087dce4 <unfinished ...>
[pid 28492] 10:26:49 <... epoll_ctl resumed> ) = -1 EPERM (Operation not permitted)
[pid 28492] 10:26:49 read(6,  <unfinished ...>
[pid 28492] 10:26:49 <... read resumed> "{\n    \"nodeDatasetMap\": [\n      "..., 512) = 143
[pid 28492] 10:26:49 close(6 <unfinished ...>
[pid 28492] 10:26:49 <... close resumed> ) = 0
[pid 28492] 10:26:49 fsync(5 <unfinished ...>
[pid 28492] 10:26:49 <... fsync resumed> ) = 0
[pid 28492] 10:26:50 write(3, "\27\3\3\0!\227Yc\nI\363\200\251\210\227\245[\372\364\244\345\32\333\260\177\260\326\277\373 \34\367"..., 38) = 38
[pid  3120] 10:26:50 <... epoll_pwait resumed> [{EPOLLIN|EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, -1, NULL, 3) = 1
[pid  3120] 10:26:50 read(3, "\27\3\3\0004\365\3\266T\261\30\230\360\v[p\233i\4\\\304\37\233\216\333\361%\4\2\343\t%"..., 6861) = 640
[pid  3120] 10:26:50 read(3, 0xc0001c4000, 6861) = -1 EAGAIN (Resource temporarily unavailable)
[pid  3120] 10:26:50 write(3, "\27\3\3\0#\215C\34<\226\266\354]\234\34l\256\17\363\216\333x\310\341\306\256\32\242\316\177\374\261"..., 40 <unfinished ...>
[pid 28466] 10:26:50 epoll_pwait(4, [{EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, 0, NULL, 0) = 1
[pid  3120] 10:26:50 <... write resumed> ) = 40
[pid 28466] 10:26:50 epoll_pwait(4, [], 128, 0, NULL, 1) = 0
[pid 28466] 10:26:50 epoll_pwait(4,  <unfinished ...>
[pid  3120] 10:26:50 write(3, "\27\3\3\2B\311\10\t\336\235\26[\344KI\v\r\205\352,\213\321\361\270\\\253\343\267\177\314\333\201"..., 583 <unfinished ...>
[pid  3120] 10:26:50 <... write resumed> ) = 583
[pid 28466] 10:26:50 <... epoll_pwait resumed> [{EPOLLIN|EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, -1, NULL, 3) = 1
[pid  3120] 10:26:50 write(3, "\27\3\3\0\31\366\350\34\20#\211\326~Rh\36\25\34Xe\211\254\321\25<}\336\331\215\251", 30 <unfinished ...>
[pid  3120] 10:26:50 <... write resumed> ) = 30
[pid 28466] 10:26:50 read(3,  <unfinished ...>
[pid  3120] 10:26:50 epoll_pwait(4, [{EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, 0, NULL, 824642211764) = 1
[pid 28466] 10:26:50 <... read resumed> "\27\3\3\0\35\376\366\343s@\6\335\204k\v\262F\267\242\30\323\266\274\357\3770\0YxM74"..., 6861) = 94
[pid  3120] 10:26:50 epoll_pwait(4,  <unfinished ...>
[pid 28466] 10:26:50 read(3,  <unfinished ...>
[pid 28466] 10:26:50 <... read resumed> 0xc0001c4000, 6861) = -1 EAGAIN (Resource temporarily unavailable)
[pid  3120] 10:26:50 <... epoll_pwait resumed> [{EPOLLIN|EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, -1, NULL, 3) = 1
[pid  3120] 10:26:50 read(3,  <unfinished ...>
[pid  3120] 10:26:50 <... read resumed> "\27\3\3\0\35r\25\332\251\263\26\212\311\304\240|\363\373\310\177\211ta\16u\251Sh\32\202\230\367"..., 6861) = 617
[pid  3120] 10:26:50 read(3,  <unfinished ...>
[pid  3120] 10:26:50 <... read resumed> 0xc0001c4000, 6861) = -1 EAGAIN (Resource temporarily unavailable)
[pid 28423] 10:26:50 epoll_pwait(4, [{EPOLLOUT, {u32=1521856264, u64=140713240407816}}], 128, 0, NULL, 0) = 1
[pid 28423] 10:26:50 epoll_pwait(4,  <unfinished ...>
^C

That part looks reasonable, but the background chatter seems excessive. I have many other golang processes running on these same boxes (including prometheus and its various exporters) and they don't generate any noticeable background CPU load. However I don't know what version of golang was used to build local-zfs-provisioner, and maybe there have been improvements in the runtime.

Otherwise, the problem may be buried somewhere in sigs.k8s.io/sig-storage-lib-external-provisioner/controller - but since that's more or less deprecated in favour of CSI, there may not be much help forthcoming.

For now I've brought my load back down by removing local-zfs-provisioner:

kubectl delete -f deployment.yaml
kubectl delete -f rbac.yaml
@asteven
Copy link
Owner

asteven commented Jan 22, 2020

I'm aware of this, also see this on my boxes.
I can not think of anything in my code causing this, almost certainly is caused by something in sigs.k8s.io/sig-storage-lib-external-provisioner. But didn't have time to pin-point it.

@asteven
Copy link
Owner

asteven commented May 13, 2020

JFYI: I'm deprecating this in favor of zfs-provisioner which is doing the same thing but is written in python.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@candlerb @asteven