High CPU usage with io.CopyBuffer

[William Tang]

I'm using k8s client-go to stream pod log to a websocket, but for some reason, the CPU usage is 100% on two thread. pprof indicates most of the time were spent on interface casting (see attachment for the pprof file) and strace reported hugh number of SIGURG signals:

12    futex(0xc00060c148, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
11    epoll_pwait(4,  <unfinished ...>
10    futex(0x49859d8, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
9     futex(0x4985ba0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
8     futex(0xc000110d48, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
6     restart_syscall(<... resuming interrupted read ...> <unfinished ...>
11    <... epoll_pwait resumed>[], 128, 0, NULL, 0) = 0
1     futex(0x4943a88, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
11    epoll_pwait(4, [{EPOLLIN|EPOLLOUT, {u32=3259498682, u64=9199583560586494138}}], 128, 310, NULL, 0) = 1
11    read(23, "\27\3\3\0$#\4\34\317W\3519KDk\34\254\207\347\326\v>\242B\300WP\25\211\245p\353\v\35Ghb\301lgg", 8192) = 41
11    read(23, 0xc000c14000, 8192)      = -1 EAGAIN (Resource temporarily unavailable)
11    write(24, "[\"73.431415\",\"o\",\"\\r\\n\\u001b[?2004l\\r\"]", 39) = 39
11    write(24, "\n", 1)                = 1
11    write(22, "\201q{\"Op\":\"stdout\",\"Data\":\"\\r\\n\\u001b[?2004l\\r\",\"SessionID\":\"cqakrrsbndmdkbss53tg\",\"ToastType\":\"\",\"Rows\":0,\"Cols\":0}\n", 115) = 115
11    epoll_pwait(4, [], 128, 0, NULL, 0) = 0
11    epoll_pwait(4, [{EPOLLIN|EPOLLOUT, {u32=3259498682, u64=9199583560586494138}}], 128, 309, NULL, 0) = 1
11    read(23, "\27\3\3\0Df\r\307\262)\374\27\322\332'\327\302\267\203\207Z\212#S\322=\\X\357\214\336\2YC\266\325keO\377b\25\274\261\375\327\261\246ZVD\362\276\f\17\20\231&\254\31\323\260,\321~\206\372#.nuZ\226", 8192) = 73
11    read(23, 0xc000c14000, 8192)      = -1 EAGAIN (Resource temporarily unavailable)
11    write(24, "[\"73.433091\",\"o\",\"strace: Process 1 attached with 8 threads\\r\\n\"]", 65) = 65
11    write(24, "\n", 1)                = 1
11    write(22, "\201~\0\213{\"Op\":\"stdout\",\"Data\":\"strace: Process 1 attached with 8 threads\\r\\n\",\"SessionID\":\"cqakrrsbndmdkbss53tg\",\"ToastType\":\"\",\"Rows\":0,\"Cols\":0}\n", 143) = 143
11    epoll_pwait(4, [], 128, 0, NULL, 0) = 0
11    epoll_pwait(4,  <unfinished ...>
6     <... restart_syscall resumed>)    = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 53744384
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 0
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 824633982976
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 824633982976
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 824633982976
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 44008193
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 824633982976
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 824633982976
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 824633982976
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 824633982976
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>
6     nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
7     <... rt_sigreturn resumed>)       = 824633982976
6     <... nanosleep resumed>NULL)      = 0
6     nanosleep({tv_sec=0, tv_nsec=10000000}, NULL) = 0
6     getpid()                          = 1
6     tgkill(1, 7, SIGURG <unfinished ...>
7     --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1, si_uid=0} ---
6     <... tgkill resumed>)             = 0
7     rt_sigreturn({mask=[]} <unfinished ...>

Any idea why?