MySQL TABLEUPDATE from VFP Cursor 2

[David Higgs]

I am trying to update a MySQL Table from changes made in a VFP Cursor.

The following code updates the field "Call_160" in Cursor "curLarge_Squares" with "Test".

SQLEXEC(SQLCONN,'SELECT * FROM &TBL_WAB_Large_sq ','curLarge_Squares')
INDEX on LG_SQUARE TAG lg_square

CURSORSETPROP("AutoIncError", .F. , "curLarge_Squares")

SET MULTILOCKS ON

=CURSORSETPROP("Buffering", 5, "curLarge_Squares")

GOTO TOP 

Replace Call_160 with "TEST" 

BROWSE 

=TABLEUPDATE()

I would now like to update the MySQL Database to match the VFP Cursor but I am not too sure how to proceed.

Any help would be much appreciated.


Regards,

David.

Recreational Developer / End User of VFP.

 

[Chris Miller]

I still can't get my head around why including CURSORSETPROP should cause this issue.

That is indeed strange, as you already found out it's not really the REPLACEs which take long.

It's good you have a READ EVENTS, so coverage would give you an idle time portion, if there is one.

One thing to try to get the grid updated as fast as possible after you filled alt_col would be to not refresh the grid, but simply set focus to it by Thisform.gridX.setfocus().



Chriss

 

[David Higgs]

Changing:

Logbook.pfMain.Logbook.gdLogbook.refresh() to Logbook.pfMain.Logbook.gdLogbook.setfocus()
made no difference.

In desperation, I removed all reference to CURSORSETPROP and the code executed in 0.422 Secs.

I then tried adding the following:

** Set optimistic Table Buffering on.
CURSORSETPROP("Buffering", 5, "curLogbook") which increased the execution time to 11.104 Secs.

P.S I just reinstated all of the previous CURSORSETPROP except the above and the code executed in 0.422 Secs.


Regards,

David.

Recreational Developer / End User of VFP.

 

[Chris Miller]

We already know that, but we now also know it's not the REPLACEs that take longer. This has to show up somewhere and you only find out by logging where the time is spent.

Chriss

 

[David Higgs]

This has to show up somewhere and you only find out by logging where the time is spent.

The time spent is within the SCAN..ENDSCAN Loop, but we know it's not the code in the Loop itself that's causing the issue. What about the CURSORSETPROP("Buffering", 5, "curLogbook"), inserting this line causes the issue, but, how (binding) / why?

Regards,

David.

Recreational Developer / End User of VFP.

 

[Chris Miller]

No, the time is not spent within the loop, extend the logging to get lines in the log until you click on a new button stopping the coverage logging.

Chriss

 

[David Higgs]

I have moved the "Coverage Log" to time the complete process for the Alt_Col call.

The Program is waiting for an instruction (Mouse Click) to initiate the routine.

SET COVERAGE TO C:\temp\scanloop.log

StartTime = SECONDS()

lookup_alt_col = "curLogbook"				
DO ALT_Row_Colours WITH lookup_alt_col		

EndTime = SECONDS()

SET COVERAGE TO

MESSAGEBOX(EndTime - StartTime)

The Start (from "idle") to finish Time ("idle") is 11 secs, there is no other code, that I can think of to include in this timed interval. It's got to be, in my humble opinion, associated with the CURSORSETPROP("Buffering", 5, "curLogbook") but that is beyond my capabilities to solve.



Regards,

David.

Recreational Developer / End User of VFP.

 

[Chris Miller]

Can you determine what time is logged overall?

Create Cursor crsTimes(duration B)
Append From C:\temp\scanloop.log
Sum duration to runningtime

Don't worry when this is about double the time. The DO ALT_Row_Colours line will be logged with the time the whole routine takes. So the individual lines logged from within the ALT_Row_Colours procedure for each line executed make their time count double.

When the lines you showed are typical I expect this to sum up to twice 0.5 seconds, so time is spent somewhere else. If, on the other hand, this sums to about twice the full duration, then it will be very interesting to see which logged lines contribute mostly to the log time.

Chriss

 

[David Higgs]

Can you determine what time is logged overall?

I've just totalled the entries for alt_row_colours and they show 11.258 Secs which is consistent to what we've been seeing all along.

I'm not sure what you what you want me to do with your code, I'm just about out of my comfort zone.

My very simplistic view is that it must something to do with:

** Set optimistic Table Buffering on.
CURSORSETPROP("Buffering", 5, "curLogbook")

because without any CURSORSETPROP code, all runs in around 0.4 Second. By just adding the above piece of code the time increase to over 11secs.

I can't see any reason to look for times outside of the loop because that is where the time is lost, the only thing is we don't know why, except possibly, the above code.



P.S - Deleted half the records and 2800 Records take approx 2.7Secs
Regards,

David.

Recreational Developer / End User of VFP.

 

[Chris Miller]

Okay, when this total reflects the time you get from the messagebox, then you have recorded what takes how long.

If all typical REPLACEs take 0.0020 up to 0.000042 that's not explaining 11 seconds. So they have to be spent elsewhere. If only some REPLACEs take long, then that's not pointing out it's REPLACE in general, but something happening in parallel.

The good news is, you have the bottleneck right in front of you.

You can create a cursor with more fields to read in the other columns of the log file, which is just CSV data. And then you can index by duration and sort descending, finding where most time is really spent.

I can just encourage you to dig a little deeper as you are very near to finding the reason. It might be a surprising thing like the USE of a table taking 9 of the 11-13 seconds, but as far as you show it's not the REPLACEs taking long. It's clear the timing is fast without CURSORSETPROPs, but if all the replaces are fast, it must be a strange side effect. If only some REPLACEs take long or each 100th REPLACE, you already know more.

Chriss

 

[David Higgs]

Just a thought, if adding or removing CURSORSETPROP BUFFER affects the timing could it be writing records to the buffer is the issue?

Regards,

David.

Recreational Developer / End User of VFP.

 

[Chris Miller]

Again, the logging you show just needs 0.000020 to update the field, that's just 1/5th of a millisecond and that includes changing the field state and buffering the value. And buffering it instead of not buffering is the crucial thing to keep the data locally cached and not let it go straight to the backend table.

As I said above it will be interesting if you find outliers say each 100th or 1000th REPLACE. Interesting are any lines which take say 0.1 seconds or even more than a second. Against all the checks you made about ODBC logging and checking the buffering state, if some REPLACEs take longer than others or if the ENDSCAN takes longer, that point out skipping from a row to the next triggers something towards MySQL, like record buffering would do. It doesn't have to be an UPDATE-SQL, it could be trying to lock the record or checking CURVAL of the MySQL table somehow. No idea, that last guess would be done for every record, though. The easiest find you could have, though is any lines outside of the loop taking long.

No matter what it is, the coverage has recorded all time spent and therefore you can now know and not guess where the time is spent.

Chriss

 

[Chris Miller]

One more very essential question: What is your connection string or how did you set DSN options for the MySQL connection. Let me see if another set of option flags would help.

Chriss

 

[David Higgs]

What is your connection string

lcStringConn="Driver={MySQL ODBC 8.0 ANSI Driver};Port=3306"+;
";Server="+SQL_Server+;
";Database="+SQL_Database+;
";Uid="+SQL_User+;
";Pwd="+SQL_Password

SQLSETPROP(0,"DispLogin",3)

SQLConn = SQLSTRINGCONNECT(lcStringConn)

Regards,

David.

Recreational Developer / End User of VFP.

 

[Chris Miller]

Okay, no special options that would cause something special. have you tried other driver versions?

And what version is the database server?

Chriss

 

[David Higgs]

Server version: 8.0.21 - MySQL Community Server - GPL
Protocol version: 10


Regards,

David.

Recreational Developer / End User of VFP.

 

[David Higgs]

Ok, I thought I'd try something different.

I've made a new 'basic' PRG File which opens the MySQL Database and loads the contents into curLogbook. The code is copied from the original test program. I included the CURSORSETPROP stuff and 2 off consecutive 'Alt_Col' Routines to simulate the two different timings that we were getting during the previous tests.

Test 1 - I disabled the CURSORSETPROP stuff and ran the program which produced timings of 0.016 Secs & 0.010 Secs.

Test 2 - I enabled the CURSORSETPROP stuff and ran the program which produced timings of 0.156 Secs and 10.588 Secs.

TSET 3 - I disabled the CURSORSETPROP stuff with the exception of CURSORSETPROP("Buffering", 5, "curLogbook") and ran the program which produced timings of 0.156 Secs and 10.610 Secs.

The above tests were carried out with 5757 Records.

This, I think, confirms my belief that that whatever is happening is happening between the SCAN...ENSCAN routine and is most likely related to the CURSORSETPROP "Buffering".


Regards,

David.

Recreational Developer / End User of VFP.

 

[Chris Miller]

The evidence is overwhelming. But there has to be a solution, because Buffering 5 (optimistic table buffering) is normal for multi user applications. And if it would always have that effect VFP would be broken.

I'd still analyze the coverage data, as it has all timing in it. The help has example code to turn the coverage data into a table for analysis in the help topic "How to: Log Code Coverage":

cFileName = GETFILE('DBF')
IF EMPTY(cFileName)
   RETURN
ENDIF

CREATE TABLE (cFileName) ;
   (duration n(7,3), ;
   class c(30), ;
   procedure c(60), ;
   line i, ;
   file c(100))
   
APPEND FROM GETFILE('log') TYPE DELIMITED

I'd change it a bit, because there is a last and 6th column that is call stack level. If you make a flat test code that does not call subroutines, that will always be 1, but it can become important when you want to dissect the durations of the lines of a subroutine which (almost) sum up to the duration of the call. Because, well, that is mainly the time the call needs, besides some behind-the-scenes milliseconds (if at all) for maintaining the callstack.

And then there is a good article from Tamar Granor at

http://tomorrowssolutionsllc.com/ConferenceSessions/Cant this application go any faster.PDF

Another thing I can point out is that not all MySQL ODBC drivers work nice with VFP, you should try older versions that are available at

https://downloads.mysql.com/archives/c-odbc/.

I'd start with the exact same driver version as the MySQL server version.

One more question I have is: Do you actually have the alt_col field in the MySQL table or do you feed it from a query that has 0 as alt_col. If it's a colun in the MySQL table, how about removing it from the updatable fields list, because the server doesn't need this at all, it's a column you only need for the frontend.

You could also put it into a separate cursor related to the logbook cursor by recno, which can be an unbuffered cursor not at all linked in any way to MySQL.


Chriss

 

[David Higgs]

Just done a quick Set Coverage test and looked at the results in Excel.

There are 17273 Lines and the Minimum time is 0.000017 Secs and the Maximum Time is 0.006869 Secs and the sum of the times is 10.863912 Secs.

It looks like the ENDSCAN is where the 0.006869 Secs comes from.

Regards,

David.

Recreational Developer / End User of VFP.

 

[Chris Miller]

Okay, I'd now filter for rows in which the duration in column ! is more than 0.003, for example. If this is always the ENDSCAN, it's the place where the loop SKIPs 1 in the logbook cursor. And then it points out VFP is only doing record buffering and not table buffering.

What is the forms Buffermode property? And if there are tables/views in the DE, what is their BufferModeOverride setting? You might get a different behaviour from these settings, even though you explicitly set tablebuffering to the logbook cursor.

Chriss