arcpy.AddMessage out of sequence on large process?

[EricCompas]

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")‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

[JoshuaBixby]

I don't see an ORDER BY clause with your first cursor, the update cursor.  Without an ORDER BY clause, no database cursor (not just ArcPy cursors) will guarantee the order of the result set.  I am guessing messages being printed out are correct based on the order the cursor is processing the records.

[EricCompas]

Thanks for the response Josh--

Even if I assume a non-ordered processing in the table rows by the cursor, the AddMessage messages still aren't in the correct order. In the message window above, multiple DeedIDs are displayed one after the other, which can only happen if CURSOR2 returns more than one record. This would lead to the J counter being larger than 1 which it isn't.

Still must be some problem with AddMessage queue....

[RebeccaStrauch__GISP]

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.

[JoshuaBixby]

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.

[EricCompas]

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