Re: [ZODB-Dev] Problem with RelStorage zodbpack

[Erik Dahl]

Shane,

Thanks for the quick response and the great tool!  I brought the app back up 
last night when I realized that this was primarily related to packing.  I'll 
give this a shot tonight when the app is quiet and I can run a pack.

-EAD



On Mar 30, 2011, at 12:34 PM, Shane Hathaway wrote:

> On 03/29/2011 07: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:
> [...]
>>   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)
> [...]
>> IntegrityError: (1062, "Duplicate entry '255911127406517196-2714-893440' for 
>> key 'PRIMARY'")
> 
> Ah, I recognize this now.  This is a minor bug that I believe has been fixed 
> for 1.5.0.  It only affects packing; it has zero impact on your application.
> 
> The bug occurs when filling the object_ref table for packing.  If you 
> interrupt the pack operation while the object_ref table is being filled, the 
> corresponding entry in object_refs_added will not be created and the next 
> attempt to pack will try again and stumble in exactly this way. The bug has 
> been solved by replacing entries in object_ref rather than just inserting 
> them.  The object_ref and object_refs_added tables are only used during 
> packing.
> 
> Perhaps the quickest thing to do is remove only the offending entries:
> 
> delete from object_refs_added where tid = 255911127406517196;
> delete from object_ref where tid = 255911127406517196;
> 
> A bit of trivia: that error message says that object 2714 in transaction 
> 255911127406517196 has at least one direct reference to object 893440.
> 
> Shane

___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
https://mail.zope.org/mailman/listinfo/zodb-dev

Re: [ZODB-Dev] Problem with RelStorage zodbpack

[Shane Hathaway]

On 03/29/2011 07: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:
[...]
>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)
[...]
> IntegrityError: (1062, "Duplicate entry '255911127406517196-2714-893440' for 
> key 'PRIMARY'")

Ah, I recognize this now.  This is a minor bug that I believe has been 
fixed for 1.5.0.  It only affects packing; it has zero impact on your 
application.

The bug occurs when filling the object_ref table for packing.  If you 
interrupt the pack operation while the object_ref table is being filled, 
the corresponding entry in object_refs_added will not be created and the 
next attempt to pack will try again and stumble in exactly this way. 
The bug has been solved by replacing entries in object_ref rather than 
just inserting them.  The object_ref and object_refs_added tables are 
only used during packing.

Perhaps the quickest thing to do is remove only the offending entries:

delete from object_refs_added where tid = 255911127406517196;
delete from object_ref where tid = 255911127406517196;

A bit of trivia: that error message says that object 2714 in transaction 
255911127406517196 has at least one direct reference to object 893440.

Shane
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
https://mail.zope.org/mailman/listinfo/zodb-dev

Re: [ZODB-Dev] Problem with RelStorage zodbpack

[Shane Hathaway]

On 03/29/2011 09:16 PM, Erik Dahl wrote:
> 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?

I haven't read the whole thread, but I will say this: it is quite safe 
to remove rows from object_ref as long as you *also* remove the 
corresponding rows from object_refs_added.  To be 100% safe, you could 
just clear both object_refs_added and object_ref before packing.

IOW, the object_ref table serves as a cache between pack operations and 
the object_refs_added table indicates how much of the object_ref cache 
is filled.

Shane
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
https://mail.zope.org/mailman/listinfo/zodb-dev

Re: [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

Re: [ZODB-Dev] Problem with RelStorage zodbpack

[Erik Dahl]

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 
>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 
> tryin

[ZODB-Dev] Problem with RelStorage zodbpack

[Erik Dahl]

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 
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



___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
https://mail.zope.org/mailman/listinfo/zodb-dev