Details
-
Type: Bug
-
Status: Closed
-
Priority: Critical
-
Resolution: Fixed
-
Fix Version/s: CU-2.6.32-042stab117.X
-
Component/s: Containers::Kernel
-
Security Level: Public
Description
>Description of problem:
after upgrade kernel from vzkernel-2.6.32-042stab116.2.x86_64
to any 042stab117 or 042stab120 we got an increase latency of network syscalls
These increase are permanent day by day, from 0 usec to thousand usecs
=====
Process 15371 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
Fri Nov 25 10:20:02 MSK 2016 = 1196 ====
0.00 0.000000 0 37 37 connect
Fri Nov 25 10:25:01 MSK 2016 = 1196 ====
0.00 0.000000 0 25 25 connect
Fri Nov 25 10:30:01 MSK 2016 = 1196 ====
3.04 0.000215 1 208 208 connect
Fri Nov 25 10:35:01 MSK 2016 = 1196 ====
4.58 0.000077 0 176 176 connect
Fri Nov 25 10:40:01 MSK 2016 = 1196 ====
0.83 0.000038 0 82 82 connect
Fri Nov 25 10:45:01 MSK 2016 = 1196 ====
5.95 0.000155 1 174 174 connect
Fri Nov 25 10:50:01 MSK 2016 = 1196 ====
1.93 0.000073 1 97 97 connect
Fri Nov 25 10:55:01 MSK 2016 = 1196 ====
27.25 0.000230 2 125 125 connect
Fri Nov 25 11:00:01 MSK 2016 = 1196 ====
3.49 0.000332 4 88 88 connect
Fri Nov 25 22:20:01 MSK 2016 = 29652 ====
99.66 0.068016 576 118 118 connect
Fri Nov 25 22:25:01 MSK 2016 = 29652 ====
88.84 0.024566 534 46 46 connect
Fri Nov 25 22:30:01 MSK 2016 = 29652 ====
99.38 0.068092 636 107 107 connect
Fri Nov 25 22:35:01 MSK 2016 = 29652 ====
92.95 0.027534 562 49 49 connect
Fri Nov 25 22:40:01 MSK 2016 = 29652 ====
90.43 0.110872 706 157 157 connect
Fri Nov 25 22:45:01 MSK 2016 = 29652 ====
94.70 0.037703 554 68 68 connect
Sat Nov 26 21:35:01 MSK 2016 = 29652 ==== 9
9.84 0.141187 1535 92 92 connect
Sat Nov 26 21:40:01 MSK 2016 = 29652 ====
98.73 0.344131 1516 227 227 connect
Sat Nov 26 21:45:01 MSK 2016 = 29652 ====
97.66 0.092836 1428 65 65 connect
Sat Nov 26 21:50:01 MSK 2016 = 29652 ====
98.04 0.118849 1606 74 74 connect
Sat Nov 26 21:55:01 MSK 2016 = 29652 ====
98.91 0.134599 1402 96 96 connect
Sat Nov 26 22:00:01 MSK 2016 = 29652 ====
94.08 0.062155 1381 45 45 connect
perf top
=====
Samples: 329K of event 'cycles', Event count (approx.): 103104286646
Overhead Shared Object Symbol
1,43% [kernel] [k] dst_ops_extend_get_rcu
0,79% [unknown] [.] 0x00007fb31cc9777f
0,75% libc-2.5.so [.] memcpy
0,68% [kernel] [k] copy_user_generic_string
0,67% [unknown] [.] 0x00007fb31ccb24fb
0,57% [unknown] [.] 0x00007fb3233a3781
0,53% libc-2.5.so [.] memmove
0,50% [unknown] [.] 0x00007fb3233a18a9
0,45% [unknown] [.] 0x00007fb31ccbfd87
0,38% [kernel] [k] page_fault
0,35% [unknown] [.] 0x00007fb31cc969b2
0,34% [unknown] [.] 0x00007fb31cccfa3f
0,33% [unknown] [.] 0x00007fb3233a04a1
0,33% libc-2.12.so [.] memcpy
0,33% mysqld [.] 0x0000000000168b37
0,31% [kernel] [k] ia32_sysenter_target
0,31% [kernel] [k] clear_page_c
0,30% [kernel] [k] fget_light
0,29% mysqld [.] _mi_rec_unpack
0,28% [unknown] [.] 0x00007fb31cc4ed30
0,28% [unknown] [.] 0x00007fb3233a3760
0,28% [unknown] [.] 0x00007fb31ccd01b0
0,28% [unknown] [.] 0x00007fb31cc97bc1
0,27% [unknown] [.] 0x00007fb31cabf400
0,27% [unknown] [.] 0x00007fb31cc96b31
0,27% [unknown] [.] 0x00007fb31cccfa0e
0,26% [unknown] [.] 0x00007fb31cd37900
0,26% [unknown] [.] 0x00007fb31cc97bbf
0,26% [unknown] [.] 0x00007fb31cc96b2f
0,25% [kernel] [k] __alloc_pages_nodemask
0,25% [unknown] [.] 0x00007fb31cccfa3d
0,24% [unknown] [.] 0x00007fb3233a3768
0,24% [unknown] [.] 0x00007fb31cccfa05
=====
The dst_ops_extend_get_rcu consumes a lot of CPU
>How reproducible:
kernel from 042stab117 and some network load
>Host OS:
CentOS release 6.8
>Guest OS:
CentOS release 6.8
>Additional info (see https://openvz.org/Reporting_OpenVZ_problem):
after upgrade kernel from vzkernel-2.6.32-042stab116.2.x86_64
to any 042stab117 or 042stab120 we got an increase latency of network syscalls
These increase are permanent day by day, from 0 usec to thousand usecs
=====
Process 15371 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
Fri Nov 25 10:20:02 MSK 2016 = 1196 ====
0.00 0.000000 0 37 37 connect
Fri Nov 25 10:25:01 MSK 2016 = 1196 ====
0.00 0.000000 0 25 25 connect
Fri Nov 25 10:30:01 MSK 2016 = 1196 ====
3.04 0.000215 1 208 208 connect
Fri Nov 25 10:35:01 MSK 2016 = 1196 ====
4.58 0.000077 0 176 176 connect
Fri Nov 25 10:40:01 MSK 2016 = 1196 ====
0.83 0.000038 0 82 82 connect
Fri Nov 25 10:45:01 MSK 2016 = 1196 ====
5.95 0.000155 1 174 174 connect
Fri Nov 25 10:50:01 MSK 2016 = 1196 ====
1.93 0.000073 1 97 97 connect
Fri Nov 25 10:55:01 MSK 2016 = 1196 ====
27.25 0.000230 2 125 125 connect
Fri Nov 25 11:00:01 MSK 2016 = 1196 ====
3.49 0.000332 4 88 88 connect
Fri Nov 25 22:20:01 MSK 2016 = 29652 ====
99.66 0.068016 576 118 118 connect
Fri Nov 25 22:25:01 MSK 2016 = 29652 ====
88.84 0.024566 534 46 46 connect
Fri Nov 25 22:30:01 MSK 2016 = 29652 ====
99.38 0.068092 636 107 107 connect
Fri Nov 25 22:35:01 MSK 2016 = 29652 ====
92.95 0.027534 562 49 49 connect
Fri Nov 25 22:40:01 MSK 2016 = 29652 ====
90.43 0.110872 706 157 157 connect
Fri Nov 25 22:45:01 MSK 2016 = 29652 ====
94.70 0.037703 554 68 68 connect
Sat Nov 26 21:35:01 MSK 2016 = 29652 ==== 9
9.84 0.141187 1535 92 92 connect
Sat Nov 26 21:40:01 MSK 2016 = 29652 ====
98.73 0.344131 1516 227 227 connect
Sat Nov 26 21:45:01 MSK 2016 = 29652 ====
97.66 0.092836 1428 65 65 connect
Sat Nov 26 21:50:01 MSK 2016 = 29652 ====
98.04 0.118849 1606 74 74 connect
Sat Nov 26 21:55:01 MSK 2016 = 29652 ====
98.91 0.134599 1402 96 96 connect
Sat Nov 26 22:00:01 MSK 2016 = 29652 ====
94.08 0.062155 1381 45 45 connect
perf top
=====
Samples: 329K of event 'cycles', Event count (approx.): 103104286646
Overhead Shared Object Symbol
1,43% [kernel] [k] dst_ops_extend_get_rcu
0,79% [unknown] [.] 0x00007fb31cc9777f
0,75% libc-2.5.so [.] memcpy
0,68% [kernel] [k] copy_user_generic_string
0,67% [unknown] [.] 0x00007fb31ccb24fb
0,57% [unknown] [.] 0x00007fb3233a3781
0,53% libc-2.5.so [.] memmove
0,50% [unknown] [.] 0x00007fb3233a18a9
0,45% [unknown] [.] 0x00007fb31ccbfd87
0,38% [kernel] [k] page_fault
0,35% [unknown] [.] 0x00007fb31cc969b2
0,34% [unknown] [.] 0x00007fb31cccfa3f
0,33% [unknown] [.] 0x00007fb3233a04a1
0,33% libc-2.12.so [.] memcpy
0,33% mysqld [.] 0x0000000000168b37
0,31% [kernel] [k] ia32_sysenter_target
0,31% [kernel] [k] clear_page_c
0,30% [kernel] [k] fget_light
0,29% mysqld [.] _mi_rec_unpack
0,28% [unknown] [.] 0x00007fb31cc4ed30
0,28% [unknown] [.] 0x00007fb3233a3760
0,28% [unknown] [.] 0x00007fb31ccd01b0
0,28% [unknown] [.] 0x00007fb31cc97bc1
0,27% [unknown] [.] 0x00007fb31cabf400
0,27% [unknown] [.] 0x00007fb31cc96b31
0,27% [unknown] [.] 0x00007fb31cccfa0e
0,26% [unknown] [.] 0x00007fb31cd37900
0,26% [unknown] [.] 0x00007fb31cc97bbf
0,26% [unknown] [.] 0x00007fb31cc96b2f
0,25% [kernel] [k] __alloc_pages_nodemask
0,25% [unknown] [.] 0x00007fb31cccfa3d
0,24% [unknown] [.] 0x00007fb3233a3768
0,24% [unknown] [.] 0x00007fb31cccfa05
=====
The dst_ops_extend_get_rcu consumes a lot of CPU
>How reproducible:
kernel from 042stab117 and some network load
>Host OS:
CentOS release 6.8
>Guest OS:
CentOS release 6.8
>Additional info (see https://openvz.org/Reporting_OpenVZ_problem):