[Search for users] [Overall Top Noters] [List of all Conferences] [Download this site]

Conference rdgeng::cics_technical

Title:Discussion of CICS technical issues
Moderator:IOSG::SMITHF
Created:Mon Mar 13 1995
Last Modified:Fri Jun 06 1997
Last Successful Update:Fri Jun 06 1997
Number of topics:192
Total number of notes:680

174.0. "problem with CICS EPI and memory leaks" by NETRIX::"ricardo.lopez@sqo.mts.dec.com" (Ricardo Lopez Cencerrado) Fri Mar 14 1997 20:36

I am developing a daemon process which serves as a gateway between a tcp
client
and CICS OSF using the EPI interface. the client sends the daemon the
transaction 
and receives back the host answer. 

The daemon is a multithreaded server, which generates two threads for every 
conection. One attending the client connection and the other taking care of
the 
EPI events received.

When the daemon runs with up to four concurrent conections ( 8 client related
threads) the daemon behaves fine. However, when more than 4 connections are
used the daemon shows memory leaks.

This is the transcript of a test with 4 connections and 8001 transactios per
connection. The daemon process is hstcom.test.14-03-97:


# ps aux | grep hstcom                                       
root      1687  0.0  0.1  248K  72K ttyp8    S  + 16:25:33     0:00.01 grep
hstcom
ricardo   1684  0.0  7.9 22.2M 4.9M ttyp2    S  + 16:24:41     0:00.74
hstcom.test.14-3-97
# echo "that was the size with no activity"
that was the size with no activity
# echo "starting now"
starting now
# ps aux | grep hstcom                     "
ricardo   1684  6.0  2.0 23.8M 1.2M ttyp2    S  + 16:24:41     0:02.05
hstcom.test.14-3-97
root      1694  0.0  0.1  248K  72K ttyp8    S  + 16:27:09     0:00.01 grep
hstcom
# ps aux | grep hstcom           
ricardo   1684  9.0  2.0 23.8M 1.2M ttyp2    S  + 16:24:41     0:15.39
hstcom.test.14-3-97
root      1697  0.0  0.1  248K  72K ttyp8    S  + 16:29:23     0:00.01 grep
hstcom
now with 2000 trans/client
# ps aux | grep hstcom             
ricardo   1684  9.0  2.0 23.8M 1.2M ttyp2    S  + 16:24:41     0:20.05
hstcom.test.14-3-97
root      1699  0.0  0.1  248K  72K ttyp8    S  + 16:30:07     0:00.01 grep
hstcom
# echo "now with 3000 trans/client"
now with 3000 trans/client
# ps aux | grep hstcom             
ricardo   1684  8.0  2.0 23.8M 1.2M ttyp2    S  + 16:24:41     0:36.30
hstcom.test.14-3-97
root      1701  0.0  0.1  248K  72K ttyp8    S  + 16:32:41     0:00.01 grep
hstcom
# echo "now with 4000 trans/client"
now with 4000 trans/client
# ps aux | grep hstcom             
ricardo   1684  8.0  2.0 23.8M 1.2M ttyp2    S  + 16:24:41     0:38.58
hstcom.test.14-3-97
root      1703  0.0  0.1  248K  72K ttyp8    S  + 16:33:05     0:00.01 grep
hstcom
# echo "now with 5000 trans/client"
now with 5000 trans/client
# ps aux | grep hstcom             
ricardo   1684  9.0  2.0 23.8M 1.2M ttyp2    S  + 16:24:41     0:47.64
hstcom.test.14-3-97
root      1705  0.0  0.1  248K  72K ttyp8    S  + 16:34:34     0:00.01 grep
hstcom
# echo "now with 6000 trans/client"
now with 6000 trans/client
# ps aux | grep hstcom             
ricardo   1684  9.0  2.0 23.8M 1.2M ttyp2    S  + 16:24:41     0:56.86
hstcom.test.14-3-97
root      1707  0.0  0.1  248K  72K ttyp8    S  + 16:36:01     0:00.01 grep
hstcom
# echo "now with 7000 trans/client"
now with 7000 trans/client
# ps aux | grep hstcom
ricardo   1684  9.0  2.0 23.8M 1.2M ttyp2    S  + 16:24:41     1:05.93
hstcom.test.14-3-97
root      1709  0.0  0.1  248K  72K ttyp8    S  + 16:37:27     0:00.01 grep
hstcom
# echo "now with all8000 tran/client"
 8000 trans/client done"
now with all 8000 trans/client done
# ps aux | grep hstcom                      
ricardo   1684  0.0  2.0 23.8M 1.2M ttyp2    S  + 16:24:41     1:15.29
hstcom.test.14-3-97
root      1711  0.0  0.1  248K  72K ttyp8    S  + 16:39:06     0:00.01 grep
hstcom
# echo "now killing the process"
now killing the process
# ps aux | grep hstcom          
ricardo   1684  0.0  2.5 23.8M 1.6M ttyp2    S  + 16:24:41     1:15.34
hstcom.test.14-3-97
root      1714  0.0  0.1  248K  72K ttyp8    S  + 16:46:10     0:00.01 grep
hstcom
# ps aux | grep hstcom          " 
root      1717  0.0  0.1  248K  72K ttyp8    S  + 16:46:30     0:00.01 grep
hstcom
# exit
# exit


This is an example when using 8 connections (16 threads) and 4001 transactions
per connection. the daemon process is hstcom.test.9clientes :


# echo "now I run a server allowed to support 8 connections"    
now I run a server allowed to support 8 connections
# echo "and run 4001 transaction in each one"
and run 4001 transaction in each one
# ps aux | grep hstcom           
root      1589  0.0  0.1  248K  72K ttyp8    S  + 13:31:32     0:00.01 grep
hstcom
ricardo   1582  0.0  5.5 25.3M 3.4M ttyp2    S  + 13:27:57     0:01.44
hstcom.test.9clientes
# echo "now all threads are running -> no process size increase is allowed"
now all threads are running -> no process size increase is allowed
# ps aux | grep hstcom
ricardo   1582  9.0  4.0 26.1M 2.5M ttyp2    S  + 13:27:57     0:08.10
hstcom.test.9clientes
root      1591  0.0  0.1  248K  72K ttyp8    S  + 13:33:13     0:00.02 grep
hstcom
# ps aux | grep "hstcom.test"    
ricardo   1582  9.0  4.3 26.3M 2.7M ttyp2    S  + 13:27:57     0:10.55
hstcom.test.9clientes
root      1593  0.0  0.1  248K  72K ttyp8    S  + 13:33:36     0:00.01 grep
hstcom.test
# echo "now we are at 500 trans/thread"
now we are at 500 trans/thread
# ps aux | grep "hstcom.test"          
ricardo   1582 10.0  4.6 26.6M 2.9M ttyp2    S  + 13:27:57     0:14.00
hstcom.test.9clientes
root      1595  0.0  0.1  248K  72K ttyp8    S  + 13:34:05     0:00.01 grep
hstcom.test
# echo "now we are at 1000 trans/thread"
now we are at 1000 trans/thread
# ps aux | grep "hstcom.test"           
ricardo   1582  9.0  6.2 27.6M 3.8M ttyp2    S  + 13:27:57     0:27.52
hstcom.test.9clientes
root      1597  0.0  0.1  248K  72K ttyp8    S  + 13:35:57     0:00.01 grep
hstcom.test
# echo "now we are at 2000 trans/thread"
now we are at 2000 trans/thread
# echo "now we are at 1500 trans/thread"
now we are at 1500 trans/thread
# ps aux | grep "hstcom.test"           
ricardo   1582 10.0  6.9 28.1M 4.3M ttyp2    S  + 13:27:57     0:34.52
hstcom.test.9clientes
root      1599  0.0  0.1  248K  72K ttyp8    S  + 13:36:55     0:00.01 grep
hstcom.test
# echo "now we are at 2000 trans/thread"
now we are at 2000 trans/thread
# ps aux | grep "hstcom.test"           
ricardo   1582  9.0  8.0 28.6M 5.0M ttyp2    S  + 13:27:57     0:44.69
hstcom.test.9clientes
root      1602  0.0  0.1  248K  72K ttyp8    S  + 13:38:19     0:00.01 grep
hstcom.test
# echo "now we are at 2500 trans/thread"
now we are at 2500 trans/thread
# ps aux | grep "hstcom.test"           
ricardo   1582  8.0  9.1 29.3M 5.6M ttyp2    S  + 13:27:57     0:54.02
hstcom.test.9clientes
root      1605  0.0  0.1  248K  72K ttyp8    S  + 13:39:38     0:00.01 grep
hstcom.test
# echo "now we are at 3000 trans/thread
now we are at 3000 trans/thread
# ps aux | grep "hstcom.test"           
ricardo   1582  9.0 10.3 30.1M 6.4M ttyp2    S  + 13:27:57     1:04.92
hstcom.test.9clientes
root      1608  0.0  0.1  248K  72K ttyp8    S  + 13:41:09     0:00.01 grep
hstcom.test
# echo "now we are at 3500 trans/thread"
now we are at 3500 trans/thread
# ^ps aux | grep "hstcom.test"           
ricardo   1582 10.0 11.4 30.8M 7.0M ttyp2    S  + 13:27:57     1:15.01
hstcom.test.9clientes
root      1611  0.0  0.1  248K  72K ttyp8    S  + 13:42:35     0:00.01 grep
hstcom.test
# echo "now we ar 3500 trans/thread"    
# echo "n 3500 trans//thread"      
# echo "test en 3500 trans/hread"
# echo "test ended f3500 trans/thread"
or 400 transthread"  
01 trans/thread"
test ended for 4001 trans/thread
# ps aux | grep "hstcom.test"            
root      1613  0.0  0.1  248K  72K ttyp8    S  + 13:44:33     0:00.01 grep
hstcom.test
ricardo   1582  0.0  7.5 31.4M 4.6M ttyp2    S  + 13:27:57     1:25.01
hstcom.test.9clientes
# echo "total growth is 31.4M - 26.1M"
total growth is 31.4M - 26.1M
# echo "now sending new conection to end the server process "
now sending new conection to end the server process 
# echo "killed ok"
killed ok


Both test have been repeated using an instrumented version with atom V2.29 for
DUnix 3.2x (actually DUnix 3.2G). 

The leak output of the test with 4 connections and 8001 transactions per
connection is:

------------------------------------------------------------------------
------------------------------------------------------------------------
Searching for new leaks in heap after program exit

A total of 88413 bytes in 192 leaks were found:

56432 bytes in 59 leaks (including 22 super leaks) created at:
    malloc                         libpthreads.so
    -----                          -----
    -----                          -----
    -----                          -----

8193 bytes in 1 leak (including 1 super leak) created at:
    malloc                         libpthreads.so
    pc = 0x2448d6b4                libc.so
    pc = 0x2448c8c0                libc.so
    __gethostbyname                libc.so
    -----                          -----
    -----                          -----
    -----                          -----

7056 bytes in 49 leaks (including 9 super leaks) created at:
    malloc                         libpthreads.so
    cma__alloc_mem                 libpthreads.so
    cma__vp_create                 libpthreads.so
    cma__int_make_thread           libpthreads.so
    pthread_create                 libpthreads.so
    -----                          -----
    -----                          -----
    -----                          -----
6192 bytes in 43 leaks (including 8 super leaks) created at:
    malloc                         libpthreads.so
    cma__alloc_mem                 libpthreads.so
    cma__get_stack                 libpthreads.so
    pc = 0x2421f0b8                libpthreads.so
    cma__get_tcb                   libpthreads.so
    pthread_create                 libpthreads.so
    -----                          -----
    -----                          -----
    -----                          -----

3232 bytes in 1 leak (including 1 super leak) created at:
    malloc                         libpthreads.so
    cma__alloc_mem                 libpthreads.so
    cma_key_create                 libpthreads.so
    pthread_keycreate              libpthreads.so
    SupTM_pthread_ThreadAllocDataSlot libcicsco.so
    CICS_EpiInitialize             libcicsepico.so
    main                           hstcom_c
1560 bytes in 4 leaks (including 4 super leaks) created at:
    malloc                         libpthreads.so
    TerSH_PackDetails              libcicsco.so
    TerEP_CallScheduler            libcicsepico.so
    TerEP_InstallTerm              libcicsepico.so
    CICS_EpiAddTerminal            libcicsepico.so
    AddTerminal                    hstcom_c
    doEPIecho                      hstcom_c
    ParentThreadMain               hstcom_c
    cma__thread_base               libpthreads.so

800 bytes in 1 leak (including 1 super leak) created at:
    malloc                         libpthreads.so
    TerEP_Initialize               libcicsepico.so
    CICS_EpiInitialize             libcicsepico.so
    main                           hstcom_c
    __start                        hstcom_c

656 bytes in 1 leak (including 1 super leak) created at:
    malloc                         libpthreads.so
    SupER_GetData                  libcicsco.so
    pc = 0x6fefba44                libcicsco.so
    SupER_StoreSymptom             libcicsco.so
    SupOS_LoadDLO2                 libcicsco.so
    CICS_EpiInitialize             libcicsepico.so
    main                           hstcom_c
    __start                        hstcom_c

576 bytes in 4 leaks created at:
    malloc                         libpthreads.so
    cma__alloc_mem                 libpthreads.so
    cma__vp_create                 libpthreads.so
    cma__int_make_thread           libpthreads.so
    pthread_create                 libpthreads.so
    AddTerminal                    hstcom_c
    doEPIecho                      hstcom_c
    ParentThreadMain               hstcom_c
    cma__thread_base               libpthreads.so

576 bytes in 4 leaks created at:
    malloc                         libpthreads.so
    cma__alloc_mem                 libpthreads.so
    cma__vp_create                 libpthreads.so
    cma__int_make_thread           libpthreads.so
    pthread_create                 libpthreads.so
    SupTM_pthread_ThreadCreate     libcicsco.so
    TerEP_RunInit                  libcicsepico.so
    SupTM_pthread_ThreadCreate     libcicsco.so
    TerEP_RunInit                  libcicsepico.so
    TerEP_InstallTerm              libcicsepico.so
    CICS_EpiAddTerminal            libcicsepico.so
    AddTerminal                    hstcom_c
    doEPIecho                      hstcom_c
    ParentThreadMain               hstcom_c
    cma__thread_base               libpthreads.so

576 bytes in 4 leaks created at:
    malloc                         libpthreads.so
    cma__alloc_mem                 libpthreads.so
    cma__get_stack                 libpthreads.so
    pc = 0x2421f0b8                libpthreads.so
    cma__get_tcb                   libpthreads.so
    pthread_create                 libpthreads.so
    SupTM_pthread_ThreadCreate     libcicsco.so
    TerEP_RunInit                  libcicsepico.so
    TerEP_InstallTerm              libcicsepico.so
    CICS_EpiAddTerminal            libcicsepico.so
    AddTerminal                    hstcom_c
    doEPIecho                      hstcom_c
    ParentThreadMain               hstcom_c
    cma__thread_base               libpthreads.so

576 bytes in 4 leaks created at:
    malloc                         libpthreads.so
    cma__alloc_mem                 libpthreads.so
    cma__vp_create                 libpthreads.so
    cma__int_make_thread           libpthreads.so
    pthread_create                 libpthreads.so
    main                           hstcom_c
    __start                        hstcom_c

432 bytes in 3 leaks (including 1 super leak) created at:
    malloc                         libpthreads.so
    cma__alloc_mem                 libpthreads.so
    cma__get_stack                 libpthreads.so
    pc = 0x2421f0b8                libpthreads.so
    cma__get_tcb                   libpthreads.so
    pthread_create                 libpthreads.so
    AddTerminal                    hstcom_c
    doEPIecho                      hstcom_c
    ParentThreadMain               hstcom_c
    cma__thread_base               libpthreads.so

432 bytes in 3 leaks (including 1 super leak) created at:
    malloc                         libpthreads.so
    cma__alloc_mem                 libpthreads.so
    cma__get_stack                 libpthreads.so
    pc = 0x2421f0b8                libpthreads.so
    cma__get_tcb                   libpthreads.so
    pthread_create                 libpthreads.so
    main                           hstcom_c
    __start                        hstcom_c

288 bytes in 2 leaks created at:
    malloc                         libpthreads.so
    cma__alloc_mem                 libpthreads.so
    cma__get_attr                  libpthreads.so
    pthread_attr_create            libpthreads.so
    SupTM_pthread_ThreadCreate     libcicsco.so
    TerEP_RunInit                  libcicsepico.so
    TerEP_InstallTerm              libcicsepico.so
    CICS_EpiAddTerminal            libcicsepico.so
    AddTerminal                    hstcom_c
    doEPIecho                      hstcom_c
    ParentThreadMain               hstcom_c
    cma__thread_base               libpthreads.so

836 bytes in 9 leaks (including 3 super leaks) below threshold of 1.0%
------------------------------------------------------------------------
------------------------------------------------------------------------

When running an instrumented version of the daemon with 8 connections and
4001 transactions per connection. the atom *3log file has a leak section 
containing:

------------------------------------------------------------------------
------------------------------------------------------------------------
Searching for new leaks in heap after program exit


A total of 4766271 bytes in 12159 leaks were found:

4680780 bytes in 12002 leaks (including 12002 super leaks) created at:
    malloc                         libpthreads.so
    TerSH_PackDetails              libcicsco.so
    TerEP_CallScheduler            libcicsepico.so
    pc = 0x6fff379c                libcicsepico.so
    CICS_EpiStartTran              libcicsepico.so
    doEPI                          hstcom_c
    doEPIecho                      hstcom_c
    ParentThreadMain               hstcom_c
    cma__thread_base               libpthreads.so

56264 bytes in 56 leaks (including 15 super leaks) created at:
    malloc                         libpthreads.so
    -----                          -----
    -----                          -----
    -----                          -----

29227 bytes in 101 leaks (including 33 super leaks) below threshold of 1.0%
------------------------------------------------------------------------
------------------------------------------------------------------------

The big leak in the second test seems to be the origin of the unexpected 
size increase of the daemon.

The daemon does not explicity call *alloc* functions or use any form of
dynamic 
memory allocation. Everything is stored in global arrays and all use of
dynamic
memory should then be related with thread operations, I guess.

As far as I understand, no special cleanup is required before or after 
calling the CICS_EpiStartTran() function and the buffer required for this
function corresponds to a static array filled with the transaction. Am I doing

something wrong when using this EPI function or is some previous step
required?

I do not understand clearly the atom output file or how it relates to the
original source code. Is there some way to make its output clearer or to
point more specifically to the bigger leak?

Is this pointing some previous error in the code and why does it seem to
behave
in a different way when using 4 connections and when using 8 connections?

Should I also post this note in the Atom conference and/or the thread
conference to
get more insight?

The test system is DEC 3000-500 with 64MB RAM, Dunix 3.2G, CICS 2.1A and the
atom version is Atom V2.29 for DUnix 3.2G.

the compile command executed for generating the instrumented version is:

cd /usr/users/ricardo/project/hstcom/
make -f test3.mk hstcom_c.third
cc -c -taso -std1 -threads -I/usr/opt/cics/include -O2 cicserver.child-fork.c
ld /usr/ccs/lib/crt0.o -taso -call_shared  -L/usr/opt/cics/lib -o hstcom_c
cicserver.child-
fork.o -lcicsepico -L/usr/opt/dce/usr/shlib/dce -lpthreads -lmach -lc_r -lc
atom hstcom_c -tool third -env threads  -L/usr/opt/cics/lib
-L/usr/opt/dce/usr/shlib -all -
heapbase taso

The full Atom output can be set available. I have not posted the full output
because it is rather long. Any clue is wellcome.


Thanks in advance,

Ricardo Lopez Cencerrado.
[Posted by WWW Notes gateway]
T.RTitleUserPersonal
Name
DateLines
174.1Please raise as an offical problem - looks like a bugMUFFIT::gerryGerry ReillyMon Mar 17 1997 16:5016
Hi,

Thank you for your clear description of the problem.  I have discussed
the memory leak with one of the engineers in IBM Hursley.  We believe
you may be seeing the same problem we have recently discovered during
the testing of V2.2.  A fix to the V2.2 EPI memory leak is currently
being developed.

Please can you raise this leak as an official problem through MCS.  They
will then enter the problem into IBM RETAIN problem system.  This will
ensure that IBM checks that your problem is the same as the V2.2
EPI memory leak, and they can then develop a patch for V2.1A.

Thanks.

-gerry
174.2Workaround...MUFFIT::gerryGerry ReillyTue Mar 18 1997 16:5528
RE: .0

It looks like you are hitting the same EPI leak that has been detected
in the V2.2 testing.  A fix will in V2.2.  If you need a fix for V2.1A
please enter a call with MCS and the fix will get back ported.

In the meantime there is a workaround.

The problem is caused by CICS not cleaning up correctly for transactions
that are started when this no listener thread in the RD.stanza) available 
to service the transaction.  The number of threads available to service
transactions is calculated using the MaxServer setting.  Therefore the 
workaround is, either-

1. Increasing the MaxServer in the RD.stanza

2. or set COMRL_RPCMULTIPLE=6 in the region's environment file.  This is
   an undocumented feature that will increase the number of threads
   available

no_of_threads = MaxServer*COMRL_RPCMULTIPLE/2 

The default value of COMRL_RPCMULTIPLE is 2.  On V3.2x system do not set
COMRL_RPCMULTIPLE too high because this will result in very large numbers
of runnable threads and the resulting context switch rate will hurt 
performance.

-gerry