I have a re-occuring problem with the XE2 (Unicode) app I'm working on. It imports data and compares the values in a TkbmMemTable to that of a TEDBTable, row by row and field by field. For some strange reason the program will slow down dramatically. Normally it will take 10 to 15 minutes to compare 660k rows, which is fine. But recently it is taking over 5 hours! It did that a couple of weeks ago and then it started running fast again so I was never able to determine the problem.

I ran AQTime on the code for 2 hours before stopping the program. I discovered most of the time (82%) is spent in TEDBEvent::WaitFor in EDBCommon. Time and TimeWithChildren=6370 seconds Hit Count=89. (Yes, that is seconds and not milliseconds). So it spends almost 2hrs in this EDB routine. (Running C/S with no AV or firewall).

The program is running in an XP VirtualBox but the same problem occurs if run outside of the VB on the Win7 host. It doesn't matter if I am running C/S (in this case) or F/S, or Debug or Release candidate. The EDB server is on the host machine that is also running the client in the VB.

The CPU is never more than 25% and there is very little disk access, about 5k/sec to 25k/sec for EDB tables and indexes. The disk access should be going full tilt since it should be traversing approx 300MB of table and 372MB of index files.

I have defragged my drive and checked 75% of the drive for bad sectors (haven't finished it yet).

I can understand if the disk was busy or CPU was at 100%, but they are both not doing much of anything for 5 hours. (I wish I could say the same

Has anyone seen this problem before?

TIA
Barry

On 11/28/2014 9:13 PM, Barry wrote:
> I ran AQTime on the code for 2 hours before stopping the program. I discovered most of the time (82%) is spent in TEDBEvent::WaitFor in EDBCommon. Time and TimeWithChildren=6370 seconds Hit Count=89. (Yes, that is seconds and not milliseconds). So it spends almost 2hrs in this EDB routine. (Running C/S with no AV or firewall).

I haven't looked at the EDB source but only WaitFor i know of (in
delphi) is one that's part of a tthread class - used to wait on thread
termination. So the real problem is why is the tedbevent thread not
exiting in a timely manner.

Can you post/describe some of the code and how it does things (are you
running in main thread or worker thread(s) etc) ?

This sounds like a very straightforward double loop (loop thru recordset
and loop thru fields for each record) so something else must be at play
here.

While not doing anything on this scale (600+K records) I do double
looping code both in edb and dbisam and have not run into anything similar.

Raul

Hi Raul,

>> I ran AQTime on the code for 2 hours before stopping the program. I discovered most of the time (82%) is spent in TEDBEvent::WaitFor in EDBCommon. Time and TimeWithChildren=6370 seconds Hit Count=89. (Yes, that is seconds and not milliseconds). So it spends almost 2hrs in this EDB routine. (Running C/S with no AV or firewall).<<

>I haven't looked at the EDB source but only WaitFor i know of (in
delphi) is one that's part of a tthread class - used to wait on thread
termination. So the real problem is why is the tedbevent thread not
exiting in a timely manner.

Can you post/describe some of the code and how it does things (are you
running in main thread or worker thread(s) etc) ?<

The application is NOT multi-threaded, all of this is happening on the main thread.

>This sounds like a very straightforward double loop (loop thru recordset
and loop thru fields for each record) so something else must be at play
here.<

Correct.

>While not doing anything on this scale (600+K records) I do double
looping code both in edb and dbisam and have not run into anything similar.<

This code used to work fine. I even restored a source backup that (I thought) worked fine and it too is slow after I recompiled it. (I will see if I can restore the .exe from backup along with the database at the time it ran fast.)

This started happening about 3 weeks ago, then went away, now it is back. I am repeating the AQTime test this time with F/S access instead of C/S. Tomorrow I will try it on another machine and see if it still runs slow. There is no other disk activity or CPU activity showing up, so the only other thing I can think of is memory fragmentation. There seems to be very little activity in the page file and there are no hard page faults that I can detect. Like I said before, the resource monitor showed the table index and table data was being accessed around 5k/second to maybe 20k/second. So I think there is something between the application and the physical data that is fouling things up. The MS event log shows nothing weird. Maybe tomorrow I will have better luck on another computer.

Barry

It's a long time since I use AQTime, but I'd say the thing you need to
be watching out for is that you are timing the right parts. A WaitFor
indicates that a thread has given work to another thread to do, and is
waiting for the signal that work is complete. The time is spent there
because the work is actually done elsewhere, and that isn't being timed
fully.

I'd be looking at networking timeouts, things that might normally work,
but which aren't being handled. Basically, the WaitFor is just a sign,
not the cause of the actual problem.

--

Matthew Jones

Barry


The only things that come to mind is some sort of AV messing around or Windows having a hissy fit.

The only thing I've used WaitFor is letting a loop (in a thread) have a snooze but allowing me to wake it up if I want - much better than sleep. However, it can be used to wait for signals back from the OS.

It doesn't sound like you're doing any writing so its probably not write locks I wouldn;t have thought it could be read locks but who knows.

Since you seem to have the source can you trace what its waiting for?

Roy Lambert

Matthew & Roy,

>Basically, the WaitFor is just a sign, not the cause of the actual problem.<
Correct. For some reason my program was waiting for something and it was taking forever to add rows to a table.

Well, I figured it out.
I am only explaining it here to help someone else who might fell into the same trap that I did.

To recap, I'm updating a destination table with rows from a source table using transactions of around 5,000 rows. I compare the fields between the two tables and the destination table gets updated if the field values have changed or new rows are added to the destination table if they are not in the source table. Also rows in the destination table are deleted if they are not in the source table. This, as Matthew pointed out, requires two loops, an outer loop for the rows, and an inner loop for the fields. A range is performed on both the source table and the destination table so only specific rows are compared. I need the range because I only process a subset of rows at a time, like a months worth of data. I may only get one month of data at a time, or several months that may not be consecutive.

So what went wrong? Why did it take 100x longer than it should have?
Well, both the source and destination tables had a filter to exclude more rows that could not be excluded by the Range. The Range would retrieve approx 5,000 rows at a time, then the filter would exclude between 0 and 10 rows at most. Do you see the problem?

Hint: I deleted all of the rows from the destination table to simplify the sync process since it then only had to add rows to the destination table. The first few dozen rows were added at a respectable 500 rows/sec. As more rows were added to the table the insertion rate dropped dramatically. After adding 1,500 rows the insert rate dropped to 5 rows/second, sometimes as low as 1 row/second. That's right, one row per second. The table had only 1 index which was not unique and there were no foreign keys or blob fields. Why was it taking so long?

Spoiler Alert. It was the filter. After each new row is inserted (or updated), the TEDBTable filter has to determine if the newly inserted row has to appear in the rows displayed by the TEDBTable or not. It appears the filter was being re-executed as each row was updated. As more rows were added inside the transaction, more rows had to be filtered. This dropped the insert rate dramatically, to only 1 row per second. When another range is applied to the tables and the process repeated, the insert rate jumped back up to 500 rows/sec then decreased as more rows were added. It didn't matter if the filter excluded any rows or not! I could have had a filter with InvoiceDate >= Date '1800-01-01' and it would still have to re-filter all of the rows after each row has been inserted/updated.

As soon as I got rid of the filter on the destination table, the insert rate stayed at 500 rows/sec..

So let that be a lesson to you. When adding a lot of rows to a table, never ever have a filter on that table.

Hopefully this will be of help to someone else how has slow inserts.

Barry
V2.13B2

Thanks for posting the explanation. Bound to help someone in the future.


--

Matthew Jones

Barry


I guessed the ending halfway through the story <vbg>

But without the clues you gave it would be difficult to spot in the wild.

Just a thought, what I've often done with things like this is use a mixture of Delphi and SQL. Generate a list (might be an array or a stringlist)  first and then walk the list doing the transfer. Overall its often more efficient just takes a bit more code.

Roy Lambert

>>
Barry wrote:

Spoiler Alert. It was the filter. After each new row is inserted (or updated), the TEDBTable filter has to determine if the newly inserted row has to appear in the rows displayed by the TEDBTable or not.
<<

Could this also be accomplished by disabling controls on the dataset?

DataSet.DisableControls;
Perform LongRunningUpdate;
DataSet.EnableControls;

Michael Riley
GySgt USMC (Ret)
www.zilchworks.com

Michael Riley wrote:

>>Could this also be accomplished by disabling controls on the dataset?<<

No. There was no TDatasource attached to either of the TEDBTables. The TEDBTables were instantiated just for the sync operation (for a non_GUI operation).

Barry