OPCFoundation / UA-.NET-Legacy

OPC Foundation Unified Architecture .NET Reference Implementations
330 stars 298 forks source link

OPC Foundation UA Com Server Wrapper Memory Leak(update due to stack thread performance) #122

Open lvchaoin opened 7 years ago

lvchaoin commented 7 years ago

I'm using Opc Foundation's UA.Net Library v1.0.341 for testing, actually the Com Server Wrapper to convert DA and Wonderware FSGateway, after run for a period of time(several days up to 15 days), the Wrapper application will have a big memory and hang up. From the wrapper log, I have the followings, it seems many TCP channel has been created, please help to advise if any suggestion. thanks.

11780 - 5/30/2017 03:05:41.699 Token #1 activated. CreatedAt = 19:05:41.668 . Lifetime = 3600000 11780 - 5/30/2017 03:05:41.714 TCPCLIENTCHANNEL SOCKET CLOSED: 0000A9AC, ChannelId=138009 11780 - 5/30/2017 03:05:41.714 Register server succeeded. Registering again in 30000 ms 11780 - 5/30/2017 03:06:12.447 Token #0 created. CreatedAt = 19:06:12.447 . Lifetime = 3600000 11780 - 5/30/2017 03:06:12.463 SECURE CHANNEL CREATED [TcpClientChannel UA-TCP 1.03.341.0] [ID=138010] Connected To: opc.tcp://localhost:4840/ [SignAndEncrypt/Basic128Rsa15/Binary] Client Certificate: [CN=UA COM Server Wrapper, DC=GSUVS022] [61C810E41ADC257DFF4C53C0750F82AA4DD47591] Server Certificate: [DC=GSUVS022.ap.corp, CN=UA Local Discovery Server, C=US, S=Arizona, L="16101 N. 82nd Street, Scottsdale", O=OPC Foundation] [3D62C49F2E4B4D65F61889D839C5D7CE68A082D9] 11780 - 5/30/2017 03:06:12.463 Token #1 activated. CreatedAt = 19:06:12.447 . Lifetime = 3600000 11780 - 5/30/2017 03:06:12.463 TCPCLIENTCHANNEL SOCKET CLOSED: 0000A77C, ChannelId=138010 11780 - 5/30/2017 03:06:12.478 RegisterServer2 failed for: opc.tcp://localhost:4840/. Falling back to RegisterServer. Exception=BadSecureChannelClosed. 11780 - 5/30/2017 03:06:12.478 Token #0 created. CreatedAt = 19:06:12.478 . Lifetime = 3600000 11780 - 5/30/2017 03:06:12.494 SECURE CHANNEL CREATED [TcpClientChannel UA-TCP 1.03.341.0] [ID=138011] Connected To: opc.tcp://localhost:4840/ [SignAndEncrypt/Basic128Rsa15/Binary] Client Certificate: [CN=UA COM Server Wrapper, DC=GSUVS022] [61C810E41ADC257DFF4C53C0750F82AA4DD47591] Server Certificate: [DC=GSUVS022.ap.corp, CN=UA Local Discovery Server, C=US, S=Arizona, L="16101 N. 82nd Street, Scottsdale", O=OPC Foundation] [3D62C49F2E4B4D65F61889D839C5D7CE68A082D9] 11780 - 5/30/2017 03:06:12.494 Token #1 activated. CreatedAt = 19:06:12.478 . Lifetime = 3600000 11780 - 5/30/2017 03:06:12.510 TCPCLIENTCHANNEL SOCKET CLOSED: 0000AA3C, ChannelId=138011 11780 - 5/30/2017 03:06:12.510 Register server succeeded. Registering again in 30000 ms 11780 - 5/30/2017 03:09:58.026 TCPSERVERCHANNEL SOCKET ATTACHED: 00009DEC, ChannelId=41 11780 - 5/30/2017 03:10:00.182 TCPSERVERCHANNEL SOCKET ATTACHED: 0000A97C, ChannelId=42 11780 - 5/30/2017 03:15:08.063 TCPSERVERCHANNEL SOCKET ATTACHED: 0000AA08, ChannelId=43 11780 - 5/30/2017 03:15:10.206 TCPSERVERCHANNEL SOCKET ATTACHED: 0000A960, ChannelId=44 ........ 11780 - 5/30/2017 04:27:30.463 TCPSERVERCHANNEL SOCKET ATTACHED: 0000AB98, ChannelId=72 11780 - 5/30/2017 04:32:38.346 TCPSERVERCHANNEL SOCKET ATTACHED: 0000A79C, ChannelId=73 11780 - 5/30/2017 04:32:40.471 TCPSERVERCHANNEL SOCKET ATTACHED: 0000AB18, ChannelId=74 11780 - 5/30/2017 04:37:48.358 TCPSERVERCHANNEL SOCKET ATTACHED: 0000AB20, ChannelId=75 ....... 11780 - 5/30/2017 09:16:49.670 TCPSERVERCHANNEL SOCKET ATTACHED: 0000AAD4, ChannelId=183 11780 - 5/30/2017 09:16:51.811 TCPSERVERCHANNEL SOCKET ATTACHED: 0000AE14, ChannelId=184 11780 - 5/30/2017 09:21:59.698 TCPSERVERCHANNEL SOCKET ATTACHED: 0000ADE8, ChannelId=185 11780 - 5/30/2017 09:22:01.839 TCPSERVERCHANNEL SOCKET ATTACHED: 0000A980, ChannelId=186 11780 - 5/30/2017 09:27:09.720 TCPSERVERCHANNEL SOCKET ATTACHED: 0000ACC8, ChannelId=187 11780 - 5/30/2017 09:27:11.861 TCPSERVERCHANNEL SOCKET ATTACHED: 0000A978, ChannelId=188 11780 - 5/30/2017 09:30:35.502 Unexpected error processing OnDataChange callback. NullReferenceException 'Object reference not set to an instance of an object.' 11780 - 5/30/2017 09:32:19.738 TCPSERVERCHANNEL SOCKET ATTACHED: 0000ACD0, ChannelId=189 11780 - 5/30/2017 09:32:21.879 TCPSERVERCHANNEL SOCKET ATTACHED: 0000ACB4, ChannelId=190 11780 - 5/30/2017 09:37:29.760 TCPSERVERCHANNEL SOCKET ATTACHED: 0000AD04, ChannelId=191 ........

lvchaoin commented 7 years ago

This should be happened in a specific condition, because I use simulation OPC da server to test with the wrapper application, I can't reproduce the issue. Thanks a lot !

lvchaoin commented 7 years ago

Monitored this issue with another round of testing for 3 days, booked 2500 tags with publish interval 1s, finally found that the increased memory is because of too many threads are created, when application frozen, there are 1144 threads and 11333 handles from the process details. And in stack's ServerBase.cs, configuration MinRequestThreadCount is 5, MaxRequestThreadCount is 100

//ServerBase.cs line 1844
public void ScheduleIncomingRequest(IEndpointIncomingRequest request)
            {
                bool tooManyOperations = false;

                // queue the request.
                lock (m_lock)   // i.e. Monitor.Enter(m_lock)
                {
                    // check able to schedule requests.
                    if (m_stopped || m_queue.Count >= m_maxRequestCount)
                    {
                        tooManyOperations = true;
                    }
                    else
                    {
                        m_queue.Enqueue(request);

                        // wake up an idle thread to handle the request if there is one
                        if (m_activeThreadCount < m_totalThreadCount)
                        {
                            Monitor.Pulse(m_lock);
                        }
                        // start a new thread to handle the request if none are idle and the pool is not full.
                        else if (m_totalThreadCount < m_maxThreadCount)
                        {
                            Thread thread = new Thread(OnProcessRequestQueue);
                            thread.IsBackground = true;
                            thread.Start(null);
                            m_totalThreadCount++;
                            m_activeThreadCount++;  // new threads start in an active state

                            Utils.Trace("Thread created: " + Thread.CurrentThread.ManagedThreadId + ". Current thread count: " + m_totalThreadCount + ". Active thread count" + m_activeThreadCount);
                        }
                    }
                }

                if (tooManyOperations)
                {
                    request.OperationCompleted(null, StatusCodes.BadTooManyOperations);
                }
            }

Above function create the thread again and again, I'm not sure if there is any dead lock cause the application cannot call an existing thread from pool. Could any one give a direction or workaround that may be helpful with this issue ?

thanks,

lvchaoin commented 7 years ago

made some changes on the statck ServerBase.cs

Changed m_queue to ConcurrentQueue instead of use lock to implement thread safe m_queue = new ConcurrentQueue<IEndpointIncomingRequest>();

ScheduleIncomingRequest function use thread pool, here I'm not sure if it has problem to the data logic, from performance perspective it's no problem

 public void ScheduleIncomingRequest(IEndpointIncomingRequest request)
            {
                bool tooManyOperations = false;

                // queue the request.

                // check able to schedule requests.
                if (m_stopped || m_activeThreadCount >= m_maxThreadCount)
                {
                    tooManyOperations = true;
                    Utils.Trace("TooManyOperations: " + Thread.CurrentThread.ManagedThreadId + ". Current thread count: " + m_totalThreadCount + ". Active thread count" + m_activeThreadCount);
                }
                else
                {
                    m_queue.Enqueue(request);
                    ThreadPool.QueueUserWorkItem(obj =>
                    {
                        if (!m_queue.Any())
                        {
                            return;
                        }

                        IEndpointIncomingRequest dealingRequest = null;
                        while (m_queue.Any() && !m_queue.TryDequeue(out dealingRequest))
                        {
                        }

                        if (dealingRequest == null)
                        {
                            return;
                        }

                        try
                        {
                            m_server.ProcessRequest(dealingRequest, null);
                        }
                        catch (Exception ex)
                        {
                            Utils.Trace("Process Request Exception: "  + ex.ToString());
                        }
                        finally
                        {
                            m_activeThreadCount--;
                        }
                    });

                    m_activeThreadCount++;

//                    // new threads start in an active state
//                    Utils.Trace("Thread created: " + Thread.CurrentThread.ManagedThreadId + ". Current thread count: " + m_totalThreadCount + ". Active thread count" + m_activeThreadCount);
                }

                if (tooManyOperations)
                {
                    request.OperationCompleted(null, StatusCodes.BadTooManyOperations);
                }
            }

By testing for 2 days, it seems threads getting stable, memory does not increase obviously. It looks like still the LOCK issue, here just the clue for somebody to optimize the application, since I'm not very familiar with the UA Stack Specification, above modification I'm not sure it will damage the logic.

thanks,