Plugin memory leak with TSMutexCreate

[traeak]

With the stats_over_http intercept handler being called with a continuation created with TSMutexCreate() each call is leaking the mutex. This is new with master and doesn't leak in ats8 or ats7 branches.

The below is the relevant valgrind log for a test run that had the stats_over_http endpoint hit 10 times.

==16953== 880 bytes in 11 blocks are definitely lost in loss record 1,184 of 1,353
==16953==    at 0x4C2BC5C: memalign (vg_replace_malloc.c:857)
==16953==    by 0x4C2BD21: posix_memalign (vg_replace_malloc.c:1020)
==16953==    by 0x4E9EB40: ats_memalign (ink_memory.cc:102)
==16953==    by 0x4EA8844: jearena::JemallocNodumpAllocator::allocate(_InkFreeList*) (JeAllocator.cc:112)
==16953==    by 0x4E9F32C: ink_freelist_new (ink_queue.cc:187)
==16953==    by 0x4F088C: alloc (Allocator.h:131)
==16953==    by 0x4F088C: new_ProxyMutex (I_Lock.h:469)
==16953==    by 0x4F088C: TSMutexCreate (InkIOCoreAPI.cc:244)
==16953==    by 0x1115143F: stats_origin (stats_over_http.c:267)
==16953==    by 0x4D6CD2: INKContInternal::handle_event(int, void*) (InkAPI.cc:1104)
==16953==    by 0x4D7B43: handleEvent (I_Continuation.h:190)
==16953==    by 0x4D7B43: APIHook::invoke(int, void*) (InkAPI.cc:1330)
==16953==    by 0x52F45D: HttpSM::state_api_callout(int, void*) (HttpSM.cc:1456)
==16953==    by 0x5282C3: call_transact_and_set_next_state (HttpSM.cc:7174)
==16953==    by 0x5282C3: HttpSM::state_read_client_request_header(int, void*) (HttpSM.cc:798)
==16953==    by 0x5261F2: HttpSM::main_handler(int, void*) (HttpSM.cc:0)

[zwoop]

What the gist, physicist ? We need a fix for this for 9.0?

[calavera]

We use stats_over_http a lot. It'd be a stopper for us to migrate to 9.0. I'm not familiar with the code enough to even start thinking on how to fix this issue 😔

[traeak]

I'll reverify this again soon and do more testing to see the scope. Have verified this shows up with valgrind running traffic_server -f -F with stats_over_http. Possibly could be related to the extra refcount operations in TSMutexCreate/TSMutexDestroy.

[calavera]

I just checked, and neither the 8.0.x branch nor the 7.1.x branch have this change:

d846436#diff-51c2386548dfd5af5047991b7b69edb0

I don't know if the solution is to revert that change, or the problem is more systemic than that.

[traeak]

It's more involved than that. The change made was good, it's likely not the issue but was hoping to tickle someone's ear who might be able to short circuit my search.

[SolidWallOfCode]

Looking at the change, it appears it is now leaking one mutex per process. That is, the mutex is allocated once and then not cleaned up at process termination. As far as I can see it's just a reporting issue, not a real leak.

[traeak]

I'm seeing multiple mutexes being leaked under the proper condition (with -f and -F options to traffic_server, both for intercept handlers and plugins that create continuations per transaction). I'm still digging down into it to see if it's only specific conditions (like when the freelists are turned off).

The once per plugin false leak you see is the global plugin mutexes. with remap stats that number increases every time I hit the stats endpoint (or run trhough a dummy plugin that creates a continuation with a TSMutexCreate() per transaction that calls TSContDestroy when the txn closes)

[randall]

I think it's more than the stats_over_http plugin as well. I saw a similar leak with prefetch:

==64759== 165,024 bytes in 1,146 blocks are definitely lost in loss record 4,167 of 4,223
==64759==    at 0x10136DFAF: malloc_zone_memalign (vg_replace_malloc.c:914)
==64759==    by 0x102031385: posix_memalign (in /usr/lib/system/libsystem_malloc.dylib)
==64759==    by 0x1013E31BD: ats_memalign (in /opt/ats9san/lib/libtscore.9.dylib)
==64759==    by 0x1013F73E2: jearena::JemallocNodumpAllocator::allocate(_InkFreeList*) (in /opt/ats9san/lib/libtscore.9.dylib)
==64759==    by 0x1013E4E11: malloc_new(_InkFreeList*) (in /opt/ats9san/lib/libtscore.9.dylib)
==64759==    by 0x1013E40D6: ink_freelist_new (in /opt/ats9san/lib/libtscore.9.dylib)
==64759==    by 0x10001547E: ClassAllocator<ProxyMutex>::alloc() (Allocator.h:131)
==64759==    by 0x100013073: new_ProxyMutex() (iocore/eventsystem/I_Lock.h:469)
==64759==    by 0x10005F9DC: TSMutexCreate (InkIOCoreAPI.cc:244)
==64759==    by 0x1051CE1E4: TSRemapDoRemap (in /opt/ats9san/var/trafficserver/2cfcc056-fb64-43b6-a237-e7717b199023/opt/ats9san/libexec/trafficserver/prefetch.so)
==64759==    by 0x1001B11D9: RemapPluginInfo::doRemap(void*, tsapi_httptxn*, _tm_remap_request_info*) (RemapPluginInfo.cc:223)
==64759==    by 0x1001B35AC: RemapPluginInst::doRemap(tsapi_httptxn*, _tm_remap_request_info*) (PluginFactory.cc:65)
==64759==    by 0x1001B83D5: RemapPlugins::run_plugin(RemapPluginInst*) (RemapPlugins.cc:56)
==64759==    by 0x1001B86D6: RemapPlugins::run_single_remap() (RemapPlugins.cc:97)
==64759==    by 0x1001BE128: RemapProcessor::perform_remap(Continuation*, HttpTransact::State*) (RemapProcessor.cc:322)
==64759==    by 0x100119844: HttpSM::do_remap_request(bool) (HttpSM.cc:4005)
==64759==    by 0x100120EA8: HttpSM::set_next_state() (HttpSM.cc:7219)
==64759==    by 0x100100176: HttpSM::call_transact_and_set_next_state(void (*)(HttpTransact::State*)) (HttpSM.cc:7174)
==64759==    by 0x100107F1B: HttpSM::handle_api_return() (HttpSM.cc:1592)
==64759==    by 0x1000FCB7B: HttpSM::do_api_callout() (HttpSM.cc:363)
==64759==    by 0x100120E69: HttpSM::set_next_state() (HttpSM.cc:7208)

Which was new to master/9.x and never seen with 8.x

[SolidWallOfCode]

Ah, if it's done per remap invocation, you'd leak if the continuation isn't cleaned up. But, if TSContDestroy is called, then that should drop the reference count on the continuation and clean up the mutex. I wonder if the problem is the continuation is scheduled for a hook that doesn't always occur. I generally also schedule on TxnClose to avoid that.