Monday, June 3, 2013

eConnect 2010 GL JE Import Slows up to 300% as Work Table Fills

I received an inquiry from a client regarding the performance of an eConnect GL journal entry import that I developed for them.  They were told that if they changed a setting in Dynamics GP, it would make eConnect faster.  I had never heard this claim before, so I figured I would give it a try and either prove or disprove it, at least when testing on one of my test servers.

Before I tested changing the Dynamics GP setting, I wanted to get a performance baseline of my JE import and record numerous import times to get an average.

I fired up my eConnect JE import that I developed for the client and added a few timers to the code.  I used the .NET System.Diagnostics.Stopwatch class to determine the time that it took for eConnect to import the journal entry transaction. 

I had a test data file that has 1,710 lines in a single JE and also has Analytical Accounting codes that my application is importing.  My import sends all 1,710 lines, plus AA data, to eConnect as a single XML document.

I ran the import several times and started recording the eConnect import durations.  After 5 imports, I was a little puzzled by the times.  They ranged from 28 seconds to 43 seconds, which seemed like a pretty big variance for the exact same JE data.  Obviously eConnect was getting slower each time the import was run.


28.71
35.35
41.47
41.93
43.03

I thought maybe it's the eConnect service holding on to SQL connections, so I restarted the eConnect service.  That didn't seem to make a difference at first, but after 7 more test imports I saw that the times suddenly dropped and then went back up.  I now had times that ranged from 15 seconds to 45 seconds, an even bigger variance that before!


42.89
27.94
15.64
16.95
31.22
33.00
45.20

Very odd, and highly suspect.  I found it very difficult to believe that the same JE data could take 15 seconds to import, and also take 45 seconds to import.  And why did the numbers decrease, and then increase again?

Then I tried restarting the SQL Server service, thinking that maybe SQL was somehow slowing down on certain operations with multiple imports.  This theory doesn't make any sense, but I wanted to rule it out.  After restarting SQL, the first time was slower, which makes sense, but subsequent imports were pretty consistent around 45 seconds.  I also tried restarting eConnect again, but the numbers stayed consistent.


56.50
43.35
43.35
45.24
45.18
44.45
46.11
43.20

So now the numbers were consistent at about 45 seconds, but why?  How did I get 15 and 16 seconds previously, which is a huge variance?

After puzzling over it for a minute, I tried one more test.  I deleted all of the unposted test JEs that I had imported so that there were no JEs in the GL work table.

Like magic, the first JE imported in under 14 seconds.


13.65
17.87
23.37
32.73
41.09

Each subsequent JE took a few seconds longer as the import time grew to 40+ seconds.

I then deleted all of the JEs and started the import again.  And again, the time dropped to under 15 seconds.


14.66
16.96
23.84
33.15
37.74
45.68

And I deleted the JEs again, just to make sure it was consistent.  And it was.


13.48
16.84



I found this to be very interesting and surprising.  My interpretation of this performance data is that the eConnect JE import performance is highly dependent upon the contents of the GL JE work tables.  Each JE that was imported added 1,710 lines to that table, and as those lines accumulated, the eConnect JE insert operation slowed. 

And my results where the times decreased and increased again were likely because I deleted all of the imported JEs in the middle of that particular test run.

I haven't looked into the eConnect stored procedures, so I don't know all that is going on, but my guess is that it probably has to do with SQL indexes and perhaps a query in the eConnect procedure that is not fully optimized.  I find it unlikely that SQL Server itself would have degraded performance after inserting a meager 6,000 records into a database table, so my suspicion is that it's a query optimization issue.  eConnect stored procedures are typically very complex and sometimes several thousand lines long, so it wouldn't surprise me if there were a few queries that weren't optimized, or can't be optimized for all scenarios.

And to be clear, this is a very specific test on one of my development servers, so I can't say that this applies in other environments, with other transaction types, or even with different types of JEs.  But my test results seem very consistent and highly reproducible, so it's something I'm going to keep in mind for other clients or projects that require high volume integrations.

Steve Endow is a Dynamics GP Certified Trainer and Dynamics GP Certified IT Professional in Los Angeles.  He is also the owner of Precipio Services, which provides Dynamics GP integrations, customizations, and automation solutions.

http://www.precipioservices.com

No comments: