[ZODB-Dev] Problem with RelStorage zodbpack

[Erik Dahl]

Ok looked a little deeper.  I think solution 2 is the way to go (ie clear the object_ref table from references that are in my range of non-packed transactions.  Does that sound right?  Statement would be:

delete from object_ref where tid > 255908476364112230;

I think once this is done the code will refill the table and go on its way. Thoughts?  

-EAD



On Mar 29, 2011, at 11:00 PM, Erik Dahl wrote:

> Ok I'm starting to understand things a little better.  The transaction 255911127406517196 was the last transaction who's references were added to the object_ref table.  But (I'm guessing because I interrupted the pack) it didn't get marked in the transaction table as packed.  In fact there are 11088 transactions in this state.  Below are the details.  I haven't fully understood the code yet (and its getting too late for productive thinking :) ) but I see to potential solutions: 
> 
> 1. Mark the transactions that have been moved to object_ref as packed but I'm guessing though that this isn't a good idea because there is other stuff that needs to happen during the pack.
> 
> 2. Remove the unpacked transactions from the object_ref table. (this seems very scary to me).
> 
> I will continue looking at the code tomorrow.  In the mean time is there an issue with continuing to use the database?  Will the orphaned object_ref records cause a problem.  (doesn't seem like they would).
> 
> Here are the details:
> 
> mysql> select tid from transaction where tid <=  255911127406517196 and packed=true order by tid desc limit 1;
> +--------------------+
> | tid                |
> +--------------------+
> | 255908476364112230 | -- the last transaction marked as packed
> +--------------------+
> 
> 
> mysql> select count(*) from transaction where tid >= 255908476364112230 and tid < 255911127406517196 order by tid desc;
> +----------+
> | count(*) |
> +----------+
> |    11088 | -- this is the number of transactions that seem to have been packed without being marked as packed.
> +----------+
> 
> mysql> select count(*) from transaction where tid > 255911127406517196;
> +----------+
> | count(*) |
> +----------+
> |   178909 | -- number of transactions that haven't made it into the object_ref table
> +----------+
> 
> mysql> select count(*) from object_ref where tid > 255911127406517196;
> +----------+
> | count(*) |
> +----------+
> |        0 | -- confirmation that the transactions after 255911127406517196 have not made it into the object_ref table
> +----------+
> 1 row in set (0.00 sec)
> 
> mysql> select count(*) from object_ref where tid >= 255911127406517196;
> +----------+
> | count(*) |
> +----------+
> |     3907 | -- confirmation again
> +----------+
> 1 row in set (0.00 sec)
> 
> mysql> select count(*) from object_ref where tid = 255911127406517196;
> +----------+
> | count(*) |
> +----------+
> |     3907 | -- and again
> +----------+
> 1 row in set (0.00 sec)
> 
> 
> 
> -EAD
> 
> 
> 
> On Mar 29, 2011, at 9:39 PM, Erik Dahl wrote:
> 
>> I was running a pack and canceled so that I could reboot my box.  After it came back up I tried to restart the pack and got this:
>> 
>> 2011-03-29 20:53:07,259 [zodbpack] INFO Opening storage (RelStorageFactory)...
>> 2011-03-29 20:53:07,457 [zodbpack] INFO Packing storage (RelStorageFactory).
>> 2011-03-29 20:53:07,464 [relstorage] INFO pack: analyzing transactions committed Tue Mar 29 20:49:48 2011 or before
>> 2011-03-29 20:53:07,465 [relstorage.adapters.packundo] INFO pre_pack: start with gc enabled
>> 2011-03-29 20:53:08,846 [relstorage.adapters.packundo] INFO discovering references from objects in 178910 transaction(s)
>> 2011-03-29 20:53:10,808 [relstorage.adapters.packundo] ERROR pre_pack: failed
>> Traceback (most recent call last):
>> File "/opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py", line 431, in pre_pack
>>   conn, cursor, pack_tid, get_references)
>> File "/opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py", line 525, in _pre_pack_with_gc
>>   self.fill_object_refs(conn, cursor, get_references)
>> File "/opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py", line 347, in fill_object_refs
>>   added += self._add_refs_for_tid(cursor, tid, get_references)
>> File "/opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py", line 397, in _add_refs_for_tid
>>   self.runner.run_many(cursor, stmt, add_rows)
>> File "/opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/scriptrunner.py", line 90, in run_many
>>   cursor.executemany(stmt, items)
>> File "build/bdist.linux-x86_64/egg/MySQLdb/cursors.py", line 206, in executemany
>>   r = r + self.execute(query, a)
>> File "build/bdist.linux-x86_64/egg/MySQLdb/cursors.py", line 174, in execute
>>   self.errorhandler(self, exc, value)
>> File "build/bdist.linux-x86_64/egg/MySQLdb/connections.py", line 36, in defaulterrorhandler
>>   raise errorclass, errorvalue
>> IntegrityError: (1062, "Duplicate entry '255911127406517196-2714-893440' for key 'PRIMARY'")
>> Traceback (most recent call last):
>> File "/opt/zenoss/bin/zodbpack", line 8, in <module>
>>   load_entry_point('RelStorage==1.4.2', 'console_scripts', 'zodbpack')()
>> 
>> 
>> I'm in process of running mysqlcheck against the database and I have the application off line.  I've looked at the code but I'm not 100% what it's trying to do.  Thoughts?  Is my database hosed? or just my packing process. 
>> 
>> 
>> -EAD
>> 
>> 
>> 
>