Search code examples
c#wcfenterprise-library

Slow response between WCF Services on same server


I'm experiencing a very strange problem in my UAT environment. I have two WCF services that communicate with each other. On a high level, my web application communicates to a Business Layer, and from there it passes wcf requests to the transaction layer which processes all requests and returns responses. The problem i'm facing is that it takes roughly 1minute for the Transaction Layer to receive the request sent by the Business Layer. There WCF services are deployed on the same server, and this application setup runs perfectly in production, so I'm not sure whats going on...

EXAMPLE:

Web-frontend sends a wcf request to the business layer to get a list of all advertisements. The business layer does some security checks(which I've removed from the example), and then simply passes the request onto the Transaction layer via another WCF request. But it takes 1 minute for the transaction layer to receive this request.

BUSINESS LAYER:

    public partial class AdsManagementService : IAdsManagementService
{
    public ListAdvertisementResponse ListAdvertisement(ListAdvertisementRequest request)
    {
        LogManager.Write("Initiated AdsManagement.AdsManagentService.ListAdvertisement()", LogCategory.Trace.ToString());

        var response = new ListAdvertisementResponse();
        response.Advertisements = new List<Advertisement>();

        LogManager.Write("Authentication token validated in AdsManagement.AdsManagentService.ListAdvertisement()", LogCategory.Event.ToString());
        var client = new AdService.AdsManagementServiceClient();

        try
        {
            response = client.ListAdvertisement(request);
            LogManager.Write("response received by AdsManagement.AdsManagentService.ListAdvertisement()", LogCategory.Event.ToString());
        }
        finally
        {
            try
            {
                client.Close();
            }
            catch (Exception ex)
            {
                LogManager.ExceptionHandler(ex);
            }
        }
    }
}

TRANSACTION LAYER

I have added log traces (BEGIN,END) to the start/end of each method call to show how long it takes to process that method.

 public ListAdvertisementResponse ListAdvertisement(ListAdvertisementRequest request)
    {
        LogManager.Write("BEGIN - ListAdvertisement", LogCategory.Event);
        var response = new ListAdvertisementResponse();

        try
        {                
            response.Advertisements = new List<AdvertisementType>();

            var ads = AdvertisementDataContextInstance.Advertisements;

            foreach (var ad in ads)
            {
                AdvertisementType advertisement = ConvertToAdvertisementType(ad);

                string filePath = AdFilePath + @"\" + ad.Code;

                if (Directory.Exists(filePath))
                {
                    string[] files = Directory.GetFiles(filePath);

                    foreach (string file in files)
                    {
                        advertisement.Files.Add(file);
                    }
                }

                response.Advertisements.Add(advertisement);
            }
        }
        catch (Exception ex)
        {
            response.ErrorAction = ResponseActionEnum.GeneralException;
            response.ErrorDetails = ex.Message;
            response.ErrorMessage = "Unable to list advertisements.";
        }

        LogManager.Write("END - ListAdvertisement", LogCategory.Event);
        return response;
    }

BUSINESS LAYER LOG TRACE

**Timestamp: 2/04/2013 9:23:08 AM**
Thread Name: 
Category: Trace
Severity: Information
Message: Initiated AdsManagement.AdsManagentService.ListAdvertisement()

**Timestamp: 2/04/2013 9:23:08 AM**
Thread Name: 
Category: Event
Severity: Information
Message: Authentication token validated in AdsManagement.AdsManagentService.ListAdvertisement()


**Timestamp: 2/04/2013 9:24:02 AM**
Thread Name: 
Category: Event
Severity: Information
Message: Response received by AdsManagement.AdsManagentService.ListAdvertisement()

**Timestamp: 2/04/2013 9:24:02 AM**
Thread Name: 
Category: Trace
Severity: Information
Message: Completed AdsManagement.AdsManagentService.ListAdvertisement()

**TRANSACTION LAYER LOG TRACE**

**2/04/2013 9:24:02 AM** - BEGIN - ListAdvertisement

**2/04/2013 9:24:02 AM** - BEGIN - ConvertToAdvertisementType

2/04/2013 9:24:02 AM - END - ConvertToAdvertisementType

2/04/2013 9:24:02 AM - BEGIN - ConvertToAdvertisementType

2/04/2013 9:24:02 AM - END - ConvertToAdvertisementType

2/04/2013 9:24:02 AM - BEGIN - ConvertToAdvertisementType

2/04/2013 9:24:02 AM - END - ConvertToAdvertisementType

**2/04/2013 9:24:02 AM** - END - ListAdvertisement


As you can see, there is roughly a 1 minute delay before the Transaction layer receives the request. I have no idea what is causing this. I think it might be the logging system (Microsoft.Practices.EnterpriseLibrary.Logging). I've noticed that it creates a separate log file almost every time it receives a request, almost as if the original log file is being kept open which stops it from writing to that file. Perhaps there is a 1 minute timeout on the logging before it decides to create a new log file and write to that?

I have the following log files in the logging directory for today's date: Every time I send a new request to the Transaction Layer, there is a 1min delay and then it creates a new log file:

RTITraceGeneral.log          02/04/2013 9:20 AM

RTIEvent.log                 02/04/2013 9:20 AM

c9d64c18-80d9-4993-b167-2070190fce51RTITraceGeneral.log    02/04/2013 9:20 AM

a7acf427-a919-4fe4-9832-d186e9e28c0cRTIEvent.log           02/04/2013 9:24 AM

8e35dbdc-3c94-4e93-866a-3affcbf5f082RTITraceGeneral.log    02/04/2013 9:24 AM 

Solution

  • I managed to figure it out. The WCF applications in IIS was set to a Multi-Process application pool, it appears that this created issues. after changing this so use a single process application pool for all WCF services, the log files are now created in a single file, and there is no more delay!