Scenario:
WCF Service call routing to COM+ application.
netTCPBinding, throttling set pretty high.
[ServiceBehavior(InstanceContextMode = InstanceContextMode.Single, ConcurrencyMode=ConcurrencyMode.Multiple)]
Service has two methods, one simply returns the string was input, the other calls the COM+ component and FOR TESTING returns the string "success" for every call. Therefore, both methods return a simple string.
Client starts 20 threads, each calling the WCF Service twice. (NOTE: A "first call" is made to prime the singleton service and also the COM+ component)
Using log4net and a Stopwatch to log the timings of the client and server calls.
NOTE
The COM+ connection is handled through a singleton, since there is a HUGE performance hit when insantiating and logging on through this component...however, I don't think this is the problem...read on!
ISSUE
If I call GetString(accountNumber), performance is very quick for all calls.
If I call GetSites(accountNumber), performance is patchy and fairly slow on most occasions.
[Apols for long lists] Attached are the log4net logs.
- Client log for GetSites()
2010-09-23 15:03:52,579 [2168] INFO Runner1:- [(null)] - 10140011 : Call took 100ms 2010-09-23 15:03:52,625 [7576] INFO Runner0:- [(null)] - 10140010 : Call took 151ms 2010-09-23 15:03:52,703 [2168] INFO Runner1:- [(null)] - 10140021 : Call took 105ms 2010-09-23 15:03:52,797 [7576] INFO Runner0:- [(null)] - 10140020 : Call took 163ms 2010-09-23 15:03:52,953 [7088] INFO Runner3:- [(null)] - 10140013 : Call took 443ms 2010-09-23 15:03:53,187 [5944] INFO Runner2:- [(null)] - 10140012 : Call took 676ms 2010-09-23 15:03:53,281 [4252] INFO Runner4:- [(null)] - 10140014 : Call took 758ms 2010-09-23 15:03:53,359 [7088] INFO Runner3:- [(null)] - 10140023 : Call took 400ms 2010-09-23 15:03:53,421 [5944] INFO Runner2:- [(null)] - 10140022 : Call took 235ms 2010-09-23 15:03:53,515 [4252] INFO Runner4:- [(null)] - 10140024 : Call took 233ms 2010-09-23 15:03:53,577 [2420] INFO Runner5:- [(null)] - 10140015 : Call took 1055ms 2010-09-23 15:03:53,639 [7416] INFO Runner7:- [(null)] - 10140017 : Call took 1116ms 2010-09-23 15:03:53,717 [6092] INFO Runner6:- [(null)] - 10140016 : Call took 1195ms 2010-09-23 15:03:53,795 [4556] INFO Runner8:- [(null)] - 10140018 : Call took 1263ms 2010-09-23 15:03:53,873 [7416] INFO Runner7:- [(null)] - 10140027 : Call took 223ms 2010-09-23 15:03:53,936 [2420] INFO Runner5:- [(null)] - 10140025 : Call took 364ms 2010-09-23 15:03:54,014 [6580] INFO Runner9:- [(null)] - 10140019 : Call took 1482ms 2010-09-23 15:03:54,092 [6092] INFO Runner6:- [(null)] - 10140026 : Call took 366ms 2010-09-23 15:03:54,170 [4556] INFO Runner8:- [(null)] - 10140028 : Call took 377ms 2010-09-23 15:03:54,232 [8156] INFO Runner10:- [(null)] - 101400110 : Call took 1692ms 2010-09-23 15:03:54,295 [6580] INFO Runner9:- [(null)] - 10140029 : Call took 285ms 2010-09-23 15:03:54,341 [8176] INFO Runner11:- [(null)] - 101400111 : Call took 1805ms 2010-09-23 15:03:54,388 [7804] INFO Runner12:- [(null)] - 101400112 : Call took 1840ms 2010-09-23 15:03:54,435 [4308] INFO Runner13:- [(null)] - 101400113 : Call took 1894ms 2010-09-23 15:03:54,497 [6992] INFO Runner14:- [(null)] - 101400114 : Call took 1951ms 2010-09-23 15:03:54,544 [8176] INFO Runner11:- [(null)] - 101400211 : Call took 193ms 2010-09-23 15:03:54,575 [8156] INFO Runner10:- [(null)] - 101400210 : Call took 351ms 2010-09-23 15:03:54,622 [7804] INFO Runner12:- [(null)] - 101400212 : Call took 239ms 2010-09-23 15:03:54,700 [4308] INFO Runner13:- [(null)] - 101400213 : Call took 255ms 2010-09-23 15:03:54,731 [6992] INFO Runner14:- [(null)] - 101400214 : Call took 237ms 2010-09-23 15:03:54,794 [6700] INFO Runner15:- [(null)] - 101400115 : Call took 2248ms 2010-09-23 15:03:54,841 [7508] INFO Runner16:- [(null)] - 101400116 : Call took 2284ms 2010-09-23 15:03:54,887 [8024] INFO Runner17:- [(null)] - 101400117 : Call took 2336ms 2010-09-23 15:03:54,934 [5412] INFO Runner19:- [(null)] - 101400119 : Call took 2368ms 2010-09-23 15:03:54,981 [6700] INFO Runner15:- [(null)] - 101400215 : Call took 181ms 2010-09-23 15:03:55,043 [7528] INFO Runner18:- [(null)] - 101400118 : Call took 2475ms 2010-09-23 15:03:55,075 [7508] INFO Runner16:- [(null)] - 101400216 : Call took 238ms 2010-09-23 15:03:55,121 [8024] INFO Runner17:- [(null)] - 101400217 : Call took 228ms 2010-09-23 15:03:55,153 [5412] INFO Runner19:- [(null)] - 101400219 : Call took 227ms 2010-09-23 15:03:55,215 [7528] INFO Runner18:- [(null)] - 101400218 : Call took 177ms
As you can see, performance is intermittent.
Here is the same test logged from the server (sw started at beginning and end of method)
2010-09-23 15:03:52,579 [6888] INFO DPCService.LoadTestService [(null)] - 10140011: Call took 91ms 2010-09-23 15:03:52,625 [6888] INFO DPCService.LoadTestService [(null)] - 10140010: Call took 44ms 2010-09-23 15:03:52,703 [6888] INFO DPCService.LoadTestService [(null)] - 10140021: Call took 71ms 2010-09-23 15:03:52,781 [6888] INFO DPCService.LoadTestService [(null)] - 10140020: Call took 70ms 2010-09-23 15:03:52,937 [6888] INFO DPCService.LoadTestService [(null)] - 10140013: Call took 139ms 2010-09-23 15:03:53,187 [6904] INFO DPCService.LoadTestService [(null)] - 10140012: Call took 340ms 2010-09-23 15:03:53,265 [6888] INFO DPCService.LoadTestService [(null)] - 10140014: Call took 262ms 2010-09-23 15:03:53,359 [6904] INFO DPCService.LoadTestService [(null)] - 10140023: Call took 153ms 2010-09-23 15:03:53,421 [6888] INFO DPCService.LoadTestService [(null)] - 10140022: Call took 138ms 2010-09-23 15:03:53,499 [4356] INFO DPCService.LoadTestService [(null)] - 10140024: Call took 139ms 2010-09-23 15:03:53,577 [6904] INFO DPCService.LoadTestService [(null)] - 10140015: Call took 202ms 2010-09-23 15:03:53,639 [6888] INFO DPCService.LoadTestService [(null)] - 10140017: Call took 195ms 2010-09-23 15:03:53,717 [4356] INFO DPCService.LoadTestService [(null)] - 10140016: Call took 170ms 2010-09-23 15:03:53,780 [6904] INFO DPCService.LoadTestService [(null)] - 10140018: Call took 209ms 2010-09-23 15:03:53,858 [4356] INFO DPCService.LoadTestService [(null)] - 10140027: Call took 131ms 2010-09-23 15:03:53,920 [6888] INFO DPCService.LoadTestService [(null)] - 10140025: Call took 275ms 2010-09-23 15:03:54,014 [4356] INFO DPCService.LoadTestService [(null)] - 10140019: Call took 133ms 2010-09-23 15:03:54,092 [6904] INFO DPCService.LoadTestService [(null)] - 10140026: Call took 283ms 2010-09-23 15:03:54,170 [6008] INFO DPCService.LoadTestService [(null)] - 10140028: Call took 288ms 2010-09-23 15:03:54,217 [6888] INFO DPCService.LoadTestService [(null)] - 101400110: Call took 279ms 2010-09-23 15:03:54,295 [4356] INFO DPCService.LoadTestService [(null)] - 10140029: Call took 274ms 2010-09-23 15:03:54,341 [6904] INFO DPCService.LoadTestService [(null)] - 101400111: Call took 247ms 2010-09-23 15:03:54,373 [6008] INFO DPCService.LoadTestService [(null)] - 101400112: Call took 196ms 2010-09-23 15:03:54,435 [6888] INFO DPCService.LoadTestService [(null)] - 101400113: Call took 202ms 2010-09-23 15:03:54,497 [6904] INFO DPCService.LoadTestService [(null)] - 101400114: Call took 139ms 2010-09-23 15:03:54,529 [6008] INFO DPCService.LoadTestService [(null)] - 101400211: Call took 146ms 2010-09-23 15:03:54,575 [4356] INFO DPCService.LoadTestService [(null)] - 101400210: Call took 270ms 2010-09-23 15:03:54,622 [6888] INFO DPCService.LoadTestService [(null)] - 101400212: Call took 174ms 2010-09-23 15:03:54,685 [6008] INFO DPCService.LoadTestService [(null)] - 101400213: Call took 145ms 2010-09-23 15:03:54,731 [4356] INFO DPCService.LoadTestService [(null)] - 101400214: Call took 147ms 2010-09-23 15:03:54,794 [6904] INFO DPCService.LoadTestService [(null)] - 101400115: Call took 288ms 2010-09-23 15:03:54,825 [6888] INFO DPCService.LoadTestService [(null)] - 101400116: Call took 198ms 2010-09-23 15:03:54,887 [6008] INFO DPCService.LoadTestService [(null)] - 101400117: Call took 188ms 2010-09-23 15:03:54,934 [4356] INFO DPCService.LoadTestService [(null)] - 101400119: Call took 177ms 2010-09-23 15:03:54,965 [6888] INFO DPCService.LoadTestService [(null)] - 101400215: Call took 134ms 2010-09-23 15:03:55,028 [6904] INFO DPCService.LoadTestService [(null)] - 101400118: Call took 230ms 2010-09-23 15:03:55,075 [6008] INFO DPCService.LoadTestService [(null)] - 101400216: Call took 175ms 2010-09-23 15:03:55,121 [7108] INFO DPCService.LoadTestService [(null)] - 101400217: Call took 213ms 2010-09-23 15:03:55,153 [4356] INFO DPCService.LoadTestService [(null)] - 101400219: Call took 220ms 2010-09-23 15:03:55,215 [6904] INFO DPCService.LoadTestService [(null)] - 101400218: Call took 168ms
As you can see, the performance is not too bad...so what's happening?
My guess is because there is a singleton in the process..how can I identify this is the problem...and more importantly, how can I resolve it?
For the COM+ connector, I use a Singleton that contains an instance of itself that the calling code references.
This means that I only have to log onto the COM+ connector once - the log on process takes about 2 seconds, killing my WCF service - and all calls route through a logged-on connector.
ANY HELP very gratefully received...