arcpy.AddMessage out of sequence on large process?

Question

Anyone encountered the message queue getting out of sequence (at least in the Python toolbox results window) on a large process? I'm running a long Python process -- looping through ~300,000 rows -- and getting messages (used for debugging) that are clearly out of sequence. Or, I've completely lost sight of how Python loops work. Any insights? Eric The message window (near the end of the process): The Python loop: # loop through all parcels sql = "PropertyID IS NOT NULL" with arcpy.da.UpdateCursor(parcel_fc,parcel_fields,sql) as cursor: i = 0 for row in cursor: propertyID = row[0] sql = "PropertyID = "+str(propertyID) arcpy.AddMessage("SQL = "+sql) # select related records in deeds table, take only 1st result with arcpy.da.SearchCursor(deed_tbl,deed_fields,sql,sql_clause=("TOP 1","ORDER BY DeedDate DESC")) as cursor2: j = 0 for row2 in cursor2: arcpy.AddMessage("DeedID = "+str(row2[1])+", DeedDate = "+str(row2[2])) row[1] = row2[1] row[2] = row2[2] row[3] = row2[3] cursor.updateRow(row) j += 1 arcpy.AddMessage("Rows found = "+str(j)) if j > 1: arcpy.AddMessage("Found more than one deed") sys.exit(0) i += 1 #if i > 1000: # arcpy.AddMessage("Rows updated ="+str(i)) # sys.exit(0) arcpy.AddMessage("Rows updated ="+str(i)) arcpy.AddMessage("AddLatestDeed.py finished")‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

EricCompas2 · Answer

Josh,

Thanks for the close read of the code. Yes, you're right, it shouldn't ever be more than 1. This was my first attempt at a cursor with the added SQL clause. The first couple of iterations of the code was returning more than the first record and that's why I have so many debug messages and was concerned with the multiple DeedIDs in the message window -- at first glance, it looked like the "TOP 1" modifier wasn't working correctly.

Eric

JoshuaBixby · Answer

The way the code is written, the J counter will never be more than 1.  The search cursor on Line 10 only retrieves 1 record, and the J counter is reset to zero every time the search cursor is recreated.  Since there is only 1 row in the search cursor, the highest that J can go is 1 before it is set back to zero.

RebeccaStrauch__GISP · Answer

I don't have a solution or work around, but I remember seeing that too with different loops.  My non-solution was to not include the print/AddMessage in the loop once I knew it was working.  I decided having messages coming out after the loops was complete would be more confusing to others running the program than having none.  Once you remove some of the "debugging" messages like SQL and row counts, it may not look as bad to the end user.

if I had to render a guess as to why it is happening, I would say the cursor is running thru faster and setting the SQL and row count variables faster than it can the updates and it's just spitting them out as they change.  I don't know if in reality that makes sense or not, but that's how mine appeared, and many times mine didn't print until the cursor was completed.

You can maybe slow it down with a sleep function if it's critical. I know for some of my scripts, I have to build in up to 5-10 second delays because my script thinks a process is complete before the system catches up.  This is mainly for fgdb deletes and renames, but the point being, sometimes script, processors, hard drives and the OS don't always seem to stay in sync.  My opinion, fwiw.