Experimental Physics and
Industrial Control System

Michael Davidsaver via Core-talk <core-talk at aps.anl.gov> · Fri, 2 Apr 2021 17:43:32 -0700

Mark,

On 4/2/21 4:28 PM, Johnson, Andrew N. via Core-talk wrote:
> Hi Mark,
> 
> On Apr 2, 2021, at 4:33 PM, Mark Rivers via Core-talk <core-talk at aps.anl.gov> wrote:
>>
>> I was tracking down some errors in an IOC with valgrind.  I found and fixed the errors in my drivers.  But I am seeing some errors in CAS-client and CAS-event.
> 
> The valgrind tools are very useful, but they can throw up a number of false positives inside EPICS, and the event you posted below is likely to be one of those since it’s talking about an area of memory that was allocated by the EPICS freeList module which manages memory allocations that are all the same size. This technique was essential with older versions of the VxWorks memory allocator which fragmented the free memory pool and thus prevented IOCs from running for long periods of time.
> 
> Michael Davidsaver may have some additional advice, but unless you’re seeing crashes associated with these I would not be too concerned about them. He has annotated many of the internal routines to teach Valgrind about the routines in Base that allocate and deallocate memory, but an “Invalid read” might be related to thread ownership and I don’t know whether there are annotations for that kind of event.

I think this is a false positive, but not one I've seen before.  So thanks for reporting it.

I don't suppose you can replicate this with softIocPVA?

details...

"Invalid read" is an access to memory which valgrind considers unallocated.  This is often
followed by "Address ... is not stack'd, malloc'd or (recently) free'd", and then a SIGSEGV.

"... inside a recently re-allocated block ..." is not a message I've seen before, and I don't
find many references to it.  I also don't see it myself, at least with softIocPVA and some
camonitor/pvmonitor.

My initial guess is that this is something to do with how the annotations in freeListLib are
being (mis)handled [1].  Possibly related to valgrind version.  I currently have:

> $ valgrind --version
> valgrind-3.14.0

[1] https://github.com/epics-base/epics-base/blob/c829ca39d873d59947d851a7b22d74d14748e336/modules/libcom/src/freeList/freeListLib.c#L88-L94

 Also see the VALGRIND_MEMPOOL_*() manipulations further down.

> - Andrew
> 
> 
> 
>>  
>> ==146728== Thread 25 CAS-client:
>> ==146728== Invalid read of size 8
>> ==146728==    at 0xE37113: db_close_events (dbEvent.c:378)
>> ==146728==    by 0xE5DB92: destroy_tcp_client (caservertask.c:1217)
>> ==146728==    by 0xE5E77D: camsgtask (camsgtask.c:161)
>> ==146728==    by 0xEB131B: start_routine (osdThread.c:412)
>> ==146728==    by 0x5EC7E24: start_thread (in /usr/lib64/libpthread-2.17.so)
>> ==146728==    by 0x704BBAC: clone (in /usr/lib64/libc-2.17.so)
>> ==146728==  Address 0x1638ee68 is 12,120 bytes inside a recently re-allocated block of size 19,464 alloc'd
>> ==146728==    at 0x4C29C23: malloc (vg_replace_malloc.c:299)
>> ==146728==    by 0xE9FBA1: freeListMalloc (freeListLib.c:95)
>> ==146728==    by 0xE9FCBD: freeListCalloc (freeListLib.c:68)
>> ==146728==    by 0xE36F71: db_init_events (dbEvent.c:297)
>> ==146728==    by 0x64E0CB: PDBProvider::PDBProvider(std::tr1::shared_ptr<epics::pvAccess::Configuration const> const&) (pdb.cpp:542)
>> ==146728==    by 0x64665D: epics::pvAccess::SingletonChannelProviderFactory<PDBProvider>::sharedInstance() (pvAccess.h:1412)
>> ==146728==    by 0x7073A5: epics::pvAccess::ChannelProviderRegistry::getProvider(std::string const&) (ChannelAccessFactory.cpp:48)
>> ==146728==    by 0x7495AE: epics::pvAccess::ServerContextImpl::loadConfiguration() (serverContext.cpp:162)
>> ==146728==    by 0x74A3FA: epics::pvAccess::ServerContext::create(epics::pvAccess::ServerContext::Config const&) (serverContext.cpp:597)
>> ==146728==    by 0x6E27B9: (anonymous namespace)::startitup() (PVAServerRegister.cpp:46)
>> ==146728==    by 0x6E31F4: startPVAServer (PVAServerRegister.cpp:71)
>> ==146728==    by 0x6E31F4: void epics::detail::call1<char const*, &(anonymous namespace)::startPVAServer>(iocshArgBuf const*) (iocshelper.h:83)
>> ==146728==    by 0xEA1C1F: iocshBody (iocsh.cpp:938)
>> ==146728==
>>  
>> ==146728== Thread 21 CAS-event:
>> ==146728== Syscall param socketcall.sendto(msg) points to uninitialised byte(s)
>> ==146728==    at 0x5ECECFB: send (in /usr/lib64/libpthread-2.17.so)
>> ==146728==    by 0xE67479: cas_send_bs_msg (caserverio.c:68)
>> ==146728==    by 0xE67A98: cas_copy_in_header (caserverio.c:287)
>> ==146728==    by 0xE5F74B: read_reply (camessage.c:513)
>> ==146728==    by 0xE38084: event_read (dbEvent.c:959)
>> ==146728==    by 0xE38084: event_task (dbEvent.c:1038)
>> ==146728==    by 0xEB131B: start_routine (osdThread.c:412)
>> ==146728==    by 0x5EC7E24: start_thread (in /usr/lib64/libpthread-2.17.so)
>> ==146728==    by 0x704BBAC: clone (in /usr/lib64/libc-2.17.so)
>> ==146728==  Address 0x1d768584 is 36 bytes inside a block of size 135,168 alloc'd
>> ==146728==    at 0x4C29C23: malloc (vg_replace_malloc.c:299)
>> ==146728==    by 0xE5E029: casExpandBuffer (caservertask.c:1341)
>> ==146728==    by 0xE5E029: casExpandSendBuffer (caservertask.c:1392)
>> ==146728==    by 0xE67A4A: cas_copy_in_header (caserverio.c:275)
>> ==146728==    by 0xE5F74B: read_reply (camessage.c:513)
>> ==146728==    by 0xE38084: event_read (dbEvent.c:959)
>> ==146728==    by 0xE38084: event_task (dbEvent.c:1038)
>> ==146728==    by 0xEB131B: start_routine (osdThread.c:412)
>> ==146728==    by 0x5EC7E24: start_thread (in /usr/lib64/libpthread-2.17.so)
>> ==146728==    by 0x704BBAC: clone (in /usr/lib64/libc-2.17.so)
>> ==146728==
>>  
>> Base 7.0.5
>> Centos 7
>> gcc 4.8.5
>>  
>> Mark
> 

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System