title: Slow response between WCF Services on same server
body: <p>I'm experiencing a very strange problem in my <code>UAT</code> environment. I have two <code>WCF</code> 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 <code>WCF</code> services are deployed on the same server, and this application setup runs perfectly in production, so I'm not sure whats going on...</p>
  
  <p><strong>EXAMPLE</strong>: </p>
  
  <p>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. </p>
  
  <p><strong>BUSINESS LAYER:</strong></p>
  
  <pre><code>    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&lt;Advertisement&gt;();
  
          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);
              }
          }
      }
  }
  </code></pre>
  
  <p><strong>TRANSACTION LAYER</strong></p>
  
  <p>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. </p>
  
  <pre><code> public ListAdvertisementResponse ListAdvertisement(ListAdvertisementRequest request)
      {
          LogManager.Write("BEGIN - ListAdvertisement", LogCategory.Event);
          var response = new ListAdvertisementResponse();
  
          try
          {                
              response.Advertisements = new List&lt;AdvertisementType&gt;();
  
              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;
      }
  </code></pre>
  
  <p><strong>BUSINESS LAYER LOG TRACE</strong></p>
  
  <pre><code>**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 
  </code></pre>