ATS 7.1 release running out of memory

[bryancall]

Here is a backtrace from a bunch of cores I am getting from 7.1. They are mostly issues with memory allocation:
[bcall@e24 ~]$ egrep '#2 |#3 |#4 |#5 ' ~/gdb.out

#2 0x00000000007857e8 in UnixNetProcessor::allocate_vc (this=0x105cc20, t=0x0) at ../../../../trafficserver/iocore/net/UnixNetProcessor.cc:460
#3 0x0000000000782bdf in NetAccept::do_blocking_accept (this=0x2b9b280253d0, t=0x2b9b281d6050) at ../../../../trafficserver/iocore/net/UnixNetAccept.cc:259
#4 0x0000000000783a1b in NetAccept::acceptLoopEvent (this=0x2b9b280253d0, event=1, e=0x2b9b281cf3c0) at ../../../../trafficserver/iocore/net/UnixNetAccept.cc:469
#5 0x0000000000515468 in Continuation::handleEvent (this=0x2b9b280253d0, event=1, data=0x2b9b281cf3c0) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/I_Continuation.h:153
#2 0x00002af5d64098d0 in ink_abort (message_format=0x2af5d64200f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002af5d640deff in ats_memalign (alignment=4096, size=4194304) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x0000000000515638 in IOBufferData::alloc (this=0x2af631221260, size_index=-4194304, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:288
#5 0x0000000000515579 in new_IOBufferData_internal (loc=0x814bf0 "memory/IOBuffer/../../../../trafficserver/iocore/cache/Cache.cc:2498", size_index=-4194304, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:264
#2 0x00002b46476178d0 in ink_abort (message_format=0x2b464762e0f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002b464761beff in ats_memalign (alignment=4096, size=33554432) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x00002b464761c938 in freelist_new (f=0x14ec000) at ../../../../trafficserver/lib/ts/ink_queue.cc:212
#5 0x00002b464761c832 in ink_freelist_new (f=0x14ec000) at ../../../../trafficserver/lib/ts/ink_queue.cc:183
#2 0x00002aed89fc08d0 in ink_abort (message_format=0x2aed89fd70f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002aed89fc4eff in ats_memalign (alignment=4096, size=987136) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x00002aed89fc5938 in freelist_new (f=0x25bb5d0) at ../../../../trafficserver/lib/ts/ink_queue.cc:212
#5 0x00002aed89fc5832 in ink_freelist_new (f=0x25bb5d0) at ../../../../trafficserver/lib/ts/ink_queue.cc:183
#2 0x00002b3d66d4a8d0 in ink_abort (message_format=0x2b3d66d610f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002b3d66d4eeff in ats_memalign (alignment=4096, size=33554432) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x00002b3d66d4f938 in freelist_new (f=0x1f50000) at ../../../../trafficserver/lib/ts/ink_queue.cc:212
#5 0x00002b3d66d4f832 in ink_freelist_new (f=0x1f50000) at ../../../../trafficserver/lib/ts/ink_queue.cc:183
#2 0x00002af391be38d0 in ink_abort (message_format=0x2af391bfa0f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002af391be7eff in ats_memalign (alignment=4096, size=3407872) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x0000000000515638 in IOBufferData::alloc (this=0x2ab464602e90, size_index=-3407872, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:288
#5 0x0000000000515579 in new_IOBufferData_internal (loc=0x814bf0 "memory/IOBuffer/../../../../trafficserver/iocore/cache/Cache.cc:2498", size_index=-3407872, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:264
#2 0x0000000000534d3d in TSHttpSsnClientAddrGet (ssnp=0x2ab21f4d1bc0) at ../../../trafficserver/proxy/InkAPI.cc:5445
#3 0x0000000000534d8b in TSHttpTxnClientAddrGet (txnp=0x2ab48b84cc00) at ../../../trafficserver/proxy/InkAPI.cc:5453
#4 0x00002aaab248f8f6 in http_hook (contp=0x275cf40, event=60006, edata=0x2ab48b84cc00) at INKPluginInit.cc:174
#5 0x000000000052a025 in INKContInternal::handle_event (this=0x275cf40, event=60006, edata=0x2ab48b84cc00) at ../../../trafficserver/proxy/InkAPI.cc:1048
#2 0x00002ab0ec4f18d0 in ink_abort (message_format=0x2ab0ec5074f0 "%s:%d: failed assertion %s") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002ab0ec4eefd4 in _ink_assert (expression=0x824641 "0", file=0x824568 "../../../../trafficserver/iocore/net/UnixNetVConnection.cc", line=188) at ../../../../trafficserver/lib/ts/ink_assert.cc:37
#4 0x0000000000786ff6 in write_signal_and_update (event=101, vc=0x2aac6cd09650) at ../../../../trafficserver/iocore/net/UnixNetVConnection.cc:188
#5 0x000000000078811d in write_to_net_io (nh=0x2ab0f4f12e60, vc=0x2aac6cd09650, thread=0x2ab0f4f0f010) at ../../../../trafficserver/iocore/net/UnixNetVConnection.cc:528
#2 0x00002b0ac8ecd8d0 in ink_abort (message_format=0x2b0ac8ee40f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002b0ac8ed1eff in ats_memalign (alignment=4096, size=4194304) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x0000000000515638 in IOBufferData::alloc (this=0x2b0b4952d020, size_index=-4194304, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:288
#5 0x0000000000515579 in new_IOBufferData_internal (loc=0x814bf0 "memory/IOBuffer/../../../../trafficserver/iocore/cache/Cache.cc:2498", size_index=-4194304, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:264
#2 0x00002ade6dcf08d0 in ink_abort (message_format=0x2ade6dd070f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002ade6dcf4eff in ats_memalign (alignment=4096, size=1048576) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x00002ade6dcf5938 in freelist_new (f=0x22fa000) at ../../../../trafficserver/lib/ts/ink_queue.cc:212
#5 0x00002ade6dcf5832 in ink_freelist_new (f=0x22fa000) at ../../../../trafficserver/lib/ts/ink_queue.cc:183
#2 0x00002b65ae07d8d0 in ink_abort (message_format=0x2b65ae0940f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002b65ae081eff in ats_memalign (alignment=4096, size=1048576) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x00002b65ae082938 in freelist_new (f=0x1a98000) at ../../../../trafficserver/lib/ts/ink_queue.cc:212
#5 0x00002b65ae082832 in ink_freelist_new (f=0x1a98000) at ../../../../trafficserver/lib/ts/ink_queue.cc:183
#2 0x00000000005d7eb8 in Http1ClientTransaction::cancel_inactivity_timeout (this=0x2b3700508a10) at ../../../../trafficserver/proxy/http/Http1ClientTransaction.h:162
#3 0x00000000005e8166 in HttpSM::state_read_server_response_header (this=0x2b3761188160, event=100, data=0x2aac688b5028) at ../../../../trafficserver/proxy/http/HttpSM.cc:1861
#4 0x00000000005eb09b in HttpSM::main_handler (this=0x2b3761188160, event=100, data=0x2aac688b5028) at ../../../../trafficserver/proxy/http/HttpSM.cc:2663
#5 0x0000000000515468 in Continuation::handleEvent (this=0x2b3761188160, event=100, data=0x2aac688b5028) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/I_Continuation.h:153
#2 0x00002b38e7893aa6 in backtrace () from /lib64/libc.so.6
#3 0x00002b38e531c1ae in ink_stack_trace_dump () at ../../../../trafficserver/lib/ts/ink_stack_trace.cc:61
#4 0x00002b38e531e4a2 in signal_crash_handler (signo=11) at ../../../../trafficserver/lib/ts/signals.cc:186
#5 0x0000000000512750 in crash_logger_invoke (signo=11, info=0x2b38f0503230, ctx=0x2b38f0503100) at ../../../trafficserver/proxy/Crash.cc:169
#2 0x00002b13bf3db8d0 in ink_abort (message_format=0x2b13bf3f20f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002b13bf3dfeff in ats_memalign (alignment=4096, size=1048576) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x00002b13bf3e0938 in freelist_new (f=0x1162000) at ../../../../trafficserver/lib/ts/ink_queue.cc:212
#5 0x00002b13bf3e0832 in ink_freelist_new (f=0x1162000) at ../../../../trafficserver/lib/ts/ink_queue.cc:183
#2 0x00002aea86f4a8d0 in ink_abort (message_format=0x2aea86f610f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002aea86f4eeff in ats_memalign (alignment=4096, size=4194304) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x0000000000515638 in IOBufferData::alloc (this=0x2aeac67764d0, size_index=-4194304, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:288
#5 0x0000000000515579 in new_IOBufferData_internal (loc=0x814bf0 "memory/IOBuffer/../../../../trafficserver/iocore/cache/Cache.cc:2498", size_index=-4194304, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:264
#2 0x00002b456ad1f8d0 in ink_abort (message_format=0x2b456ad360f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002b456ad23eff in ats_memalign (alignment=4096, size=1048576) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x00002b456ad24938 in freelist_new (f=0x11f4000) at ../../../../trafficserver/lib/ts/ink_queue.cc:212
#5 0x00002b456ad24832 in ink_freelist_new (f=0x11f4000) at ../../../../trafficserver/lib/ts/ink_queue.cc:183
#2 0x00002ad23c1bd8d0 in ink_abort (message_format=0x2ad23c1d40f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002ad23c1c1eff in ats_memalign (alignment=4096, size=3670016) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x0000000000515638 in IOBufferData::alloc (this=0x2ab1e5d80c50, size_index=-3670016, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:288
#5 0x0000000000515579 in new_IOBufferData_internal (loc=0x814bf0 "memory/IOBuffer/../../../../trafficserver/iocore/cache/Cache.cc:2498", size_index=-3670016, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:264
#2 0x00002b5947fa88d0 in ink_abort (message_format=0x2b5947fbf0f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002b5947faceff in ats_memalign (alignment=4096, size=1048576) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x00002b5947fad938 in freelist_new (f=0x277c000) at ../../../../trafficserver/lib/ts/ink_queue.cc:212
#5 0x00002b5947fad832 in ink_freelist_new (f=0x277c000) at ../../../../trafficserver/lib/ts/ink_queue.cc:183
#2 0x00002ae0db1c58d0 in ink_abort (message_format=0x2ae0db1dc0f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002ae0db1c9eff in ats_memalign (alignment=4096, size=2883584) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x0000000000515638 in IOBufferData::alloc (this=0x2ab4f572a680, size_index=-2883584, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:288
#5 0x0000000000515579 in new_IOBufferData_internal (loc=0x814bf0 "memory/IOBuffer/../../../../trafficserver/iocore/cache/Cache.cc:2498", size_index=-2883584, type=MEMALIGNED) at /home/bcall/dev/yahoo/build/_build/ats_build/../../trafficserver/iocore/eventsystem/P_IOBuffer.h:264
#2 0x00000000005d7e7b in Http1ClientTransaction::set_inactivity_timeout (this=0x2b419810b910, timeout_in=30000000000) at ../../../../trafficserver/proxy/http/Http1ClientTransaction.h:156
#3 0x00000000005f642f in HttpSM::do_setup_post_tunnel (this=0x2ab4abe81d80, to_vc_type=HTTP_SERVER_VC) at ../../../../trafficserver/proxy/http/HttpSM.cc:5719
#4 0x00000000005e8866 in HttpSM::state_send_server_request_header (this=0x2ab4abe81d80, event=103, data=0x2aac6c2e5520) at ../../../../trafficserver/proxy/http/HttpSM.cc:2002
#5 0x00000000005eb09b in HttpSM::main_handler (this=0x2ab4abe81d80, event=103, data=0x2aac6c2e5520) at ../../../../trafficserver/proxy/http/HttpSM.cc:2663
#2 0x00002af1d09478d0 in ink_abort (message_format=0x2af1d095e0f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002af1d094beff in ats_memalign (alignment=4096, size=67108864) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x00002af1d094c938 in freelist_new (f=0x1714000) at ../../../../trafficserver/lib/ts/ink_queue.cc:212
#5 0x00002af1d094c832 in ink_freelist_new (f=0x1714000) at ../../../../trafficserver/lib/ts/ink_queue.cc:183
#2 0x00002b461e6fd8d0 in ink_abort (message_format=0x2b461e7140f0 "couldn't allocate %zu bytes at alignment %zu - insufficient memory") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002b461e701eff in ats_memalign (alignment=4096, size=1048576) at ../../../../trafficserver/lib/ts/ink_memory.cc:108
#4 0x00002b461e702938 in freelist_new (f=0x17e4000) at ../../../../trafficserver/lib/ts/ink_queue.cc:212
#5 0x00002b461e702832 in ink_freelist_new (f=0x17e4000) at ../../../../trafficserver/lib/ts/ink_queue.cc:183
#2 0x0000000000000000 in ?? ()
#2 0x00002b4111ee08d0 in ink_abort (message_format=0x2b4111ef7038 "couldn't allocate %zu bytes") at ../../../../trafficserver/lib/ts/ink_error.cc:99
#3 0x00002b4111ee4db6 in ats_malloc (size=106496) at ../../../../trafficserver/lib/ts/ink_memory.cc:60
#4 0x0000000000690bd0 in LogFile::write_ascii_logbuffer3 (this=0x2d51e70, buffer_header=0x2ab4bb11c800, alt_format=0x0) at ../../../../trafficserver/proxy/logging/LogFile.cc:457
#5 0x00000000006906ca in LogFile::preproc_and_try_delete (this=0x2d51e70, lb=0x2b41a570cbb0) at ../../../../trafficserver/proxy/logging/LogFile.cc:331
#2 0x0000000000000000 in ?? ()

[shinrich]

Any indication of object buildup in a particular type of object pool?

[shinrich]

I saw stacks like this when I was running with the free list disabled (-f).

[scw00]

We have met the same situation in our product env in 6.2.X. We try to modify max_map_count, the kernel variable, and it work well.

In Short, it may too much map-nnons in process, and linux limits it by max_map_count ! Using "pmap pid" could get more info.

[bryancall]

There is an issue with the number of real TCP connections, the stats that keeps track of the number of current client connections, and the number of http2 client sessions. All of them disagree:

[bcall@e24 ~]$ ss -tn | awk '{print $4}' | grep -c :80 ; ss -tn | awk '{print $4}' | grep -c :443; traffic_ctl metric get proxy.process.net.accepts_currently_open; traffic_ctl metric match current_client_sessions; traffic_ctl metric match http.current_client_connections
245
1330
proxy.process.net.accepts_currently_open 9
proxy.process.http2.current_client_sessions 41771
proxy.process.http.current_client_connections 1

[shinrich]

I installed on a machine with a higher load, and it fails in ats_memalign from freelist_new within 2 minutes of traffic. Watching top the amount of memory used by the process is much less than the amount of available memory (10% in use). Could be that top is delayed in getting updated.

The same build (or very similar build) has run for days on a machine with lower (1/3) of the traffic load.

[shinrich]

Built with jemalloc and installed on same machine. Does not crash anymore, but the load average is crazy (25-30). spinlock shows up as 25% CPU in perf top and IOBuffer::read_avail shows up in second spot at 7-12% cpu.

I did notice that as part of fix for TS-1822, @PSUdaemon removes a call to mallopt. Perhaps we still need to set a constraint for the straight glibc malloc?

[mingzym]

I'd suggest you should take a look what @scw00 commented, base on man malloc:

Normally, malloc() allocates memory from the heap, and adjusts the size of the heap as required, using sbrk(2).  When allocating blocks of memory larger than MMAP_THRESHOLD bytes, the glibc malloc()  implementation  allocates
       the  memory  as  a  private anonymous mapping using mmap(2).  MMAP_THRESHOLD is 128 kB by default, but is adjustable using mallopt(3).  Allocations performed using mmap(2) are unaffected by the RLIMIT_DATA resource limit (see
       getrlimit(2)).

a malloc may tigger a mmap() when doing the real alloc, so things may get complex with default sysctrl config, please take a look.

and I thinks that before TS-1822 the default M_MMAP_MAX = 2097152, no harm and it will bump the default 64K to 2M, it is a good if you used many mmap in your system.

[bryancall]

The problem I am seeing with 7.1 has to do with http2 client sessions not closing and releasing the MIOBuffer. I am running a test with 7.0.0 and seeing if the issue was there too.

[bryancall]

Information from 7.0.0 release running in production on the same server:

[bcall@e24 crash]$ ss -tn | awk '{print $4}' | grep -c ':80$' ; ss -tn | awk '{print $4}' | grep -c ':443$'; traffic_ctl metric get proxy.process.net.connections_currently_open; traffic_ctl metric match current_client_sessions; traffic_ctl metric match http.current_client_connections; grep HttpSM.cc:6485 /home/y/logs/trafficserver/traffic.out; ss -s
2658
54005
proxy.process.net.connections_currently_open 78128
proxy.process.http2.current_client_sessions 37296
proxy.process.http.current_client_connections 14835
   7748180 |    7669410 |           2563600384 |      32545 | memory/IOBuffer/../../../../trafficserver/proxy/http/HttpSM.cc:6485
  27926828 |   27884703 |           1371799552 |      32564 | memory/IOBuffer/../../../../trafficserver/proxy/http/HttpSM.cc:6485
  30031206 |   29999975 |           1009647616 |      32328 | memory/IOBuffer/../../../../trafficserver/proxy/http/HttpSM.cc:6485
  33306877 |   33252469 |           1767923712 |      32493 | memory/IOBuffer/../../../../trafficserver/proxy/http/HttpSM.cc:6485
  87611972 |   87588769 |            752799744 |      32444 | memory/IOBuffer/../../../../trafficserver/proxy/http/HttpSM.cc:6485
Total: 63568 (kernel 65390)
TCP:   97209 (estab 63217, closed 31012, orphaned 2935, synrecv 0, timewait 31012/0), ports 17009

Transport Total     IP        IPv6
*	  65390     -         -
RAW	  0         0         0
UDP	  28        12        16
TCP	  66197     50229     15968
INET	  66225     50241     15984
FRAG	  0         0         0